Project

General

Profile

Actions

Bug #17102

closed

teuthology.log logging regression

Added by Ilya Dryomov over 7 years ago. Updated over 7 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Core
% Done:

0%

Source:
other
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Crash signature (v1):
Crash signature (v2):

Description

Starting with merge 6028c953cc43 ("Merge pull request #914 from ceph/wip-orchestra-logging"), stdout/stderr output is no longer streamed, but rather dumped in one go after the workunit completes. Compare timestamps:

http://qa-proxy.ceph.com/teuthology/teuthology-2016-07-20_02:15:03-krbd-jewel-testing-basic-smithi/325119/teuthology.log

2016-07-25T04:33:43.214 INFO:teuthology.orchestra.run.smithi051:Running: 'sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage ceph_test_librbd_fsx -d -W -R -p 100 -P /home/ubuntu/cephtest/archive -r 512 -w 512 -t 512 -h 512 -l 250000000 -S 0 -N 10000 -K -U pool_client.0 image_client.0'
2016-07-25T04:33:43.329 INFO:teuthology.orchestra.run.smithi051.stdout:mapped writes DISABLED
2016-07-25T04:33:43.330 INFO:teuthology.orchestra.run.smithi051.stdout:mapped reads DISABLED
2016-07-25T04:33:43.330 INFO:teuthology.orchestra.run.smithi051.stdout:Seed set to 6423
2016-07-25T04:33:43.330 INFO:teuthology.orchestra.run.smithi051.stdout:krbd mode enabled
2016-07-25T04:33:51.595 INFO:teuthology.orchestra.run.smithi051.stdout:1 write    0x3caaa00 thru    0x3cb2fa2    (0x85a3 bytes)
...
2016-07-25T04:39:10.992 INFO:teuthology.orchestra.run.smithi051.stdout:9998 trunc    from 0xa003e00 to 0xa352e00
2016-07-25T04:39:11.025 INFO:teuthology.orchestra.run.smithi051.stdout:9999 write    0xd5c6200 thru    0xd5cf4af    (0x92b0 bytes)
2016-07-25T04:39:11.027 INFO:teuthology.orchestra.run.smithi051.stdout:10000 punch    from 0xc54a000 to 0xc555200, (0xb200 bytes)
2016-07-25T04:39:11.239 INFO:teuthology.orchestra.run.smithi051.stdout:checking clone #85, image image_client.0-clone85 against file /home/ubuntu/cephtest/archive/fsx-image_client.0-parent86
2016-07-25T04:41:08.550 INFO:teuthology.orchestra.run.smithi051.stdout:All operations completed A-OK!
2016-07-25T04:41:08.569 DEBUG:teuthology.parallel:result is None

and

http://qa-proxy.ceph.com/teuthology/teuthology-2016-07-24_02:15:02-krbd-jewel-testing-basic-smithi/331018/teuthology.log

2016-07-31T04:15:27.445 INFO:teuthology.orchestra.run.smithi035:Running: 'sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage ceph_test_librbd_fsx -d -W -R -p 100 -P /home/ubuntu/cephtest/archive -r 512 -w 512 -t 512 -h 512 -l 250000000 -S 0 -N 10000 -K -U pool_client.0 image_client.0'
2016-07-31T04:21:36.963 INFO:teuthology.orchestra.run.smithi035.stdout:mapped writes DISABLED
2016-07-31T04:21:36.963 INFO:teuthology.orchestra.run.smithi035.stdout:mapped reads DISABLED
2016-07-31T04:21:36.963 INFO:teuthology.orchestra.run.smithi035.stdout:Seed set to 3727
2016-07-31T04:21:36.964 INFO:teuthology.orchestra.run.smithi035.stdout:krbd mode enabled
2016-07-31T04:21:36.964 INFO:teuthology.orchestra.run.smithi035.stdout:skipping zero size read
...
2016-07-31T04:22:22.490 INFO:teuthology.orchestra.run.smithi035.stdout:9997 read    0x2503800 thru    0x250d3a9    (0x9baa bytes)
2016-07-31T04:22:22.490 INFO:teuthology.orchestra.run.smithi035.stdout:9999 trunc    from 0xdba7c00 to 0x3d0c200
2016-07-31T04:22:22.491 INFO:teuthology.orchestra.run.smithi035.stdout:10000 punch    from 0x3445200 to 0x3451600, (0xc400 bytes)
2016-07-31T04:22:22.491 INFO:teuthology.orchestra.run.smithi035.stdout:checking clone #69, image image_client.0-clone69 against file /home/ubuntu/cephtest/archive/fsx-image_client.0-parent70
2016-07-31T04:22:22.491 INFO:teuthology.orchestra.run.smithi035.stdout:All operations completed A-OK!
2016-07-31T04:22:22.492 DEBUG:teuthology.parallel:result is None

I suspect this also goes for scripts that set -x. If the node crashes, the log goes with it...

Actions #1

Updated by Zack Cerza over 7 years ago

  • Status changed from New to In Progress
  • Assignee set to Zack Cerza
Actions #2

Updated by Zack Cerza over 7 years ago

  • Status changed from In Progress to Fix Under Review
Actions #3

Updated by Zack Cerza over 7 years ago

  • Status changed from Fix Under Review to Resolved
Actions

Also available in: Atom PDF