Bug #13005

[Crunch2] All stdout gets the same timestamp and other logging problems

Added by Tom Morris 11 months ago. Updated 10 months ago.

Status:
New
Priority:
Normal
Assigned To:
-
Category:
-
Target version:
Start date:
Due date:
% Done:

0%

Estimated time:
Story points:
-

Description

The log below present a couple of different problems:
  1. first, and most important, every line of stdout has same timestamp, exact to the microsecond, which I know can't be true since the job is creating files, running scripts, etc which certainly take at least a second or two
  2. the lines aren't ordered by timestamp
2018-01-24T21:56:45.908601988Z cpu 39.1400 user 5.8800 sys 16 cpus -- interval 10.0000 seconds 2.0500 user 0.2000 sys
2018-01-24T21:56:47.976272218Z Starting vcfMQM.pl
2018-01-24T21:56:47.976272218Z Creating temp.csv
2018-01-24T21:56:47.976272218Z Starting chipVCFconversionCSV.pl
2018-01-24T21:56:47.976272218Z Starting newMerge.py
2018-01-24T21:56:47.976272218Z Starting FPFNcalc_v2.pl
2018-01-24T21:56:47.976272218Z Removing temp file
2018-01-24T21:56:47.976272218Z Started counting
2018-01-24T21:56:47.976272218Z 99.0163934426
2018-01-24T21:56:47.976272218Z All done!!!
2018-01-24T21:56:47.525899369Z ref loaded
2018-01-24T21:42:05.607639432Z Starting Docker container id '91ece422b5b3d16b646e77441b06522e92e74a2853fb5b30cdef8d5c3aaf3b28'
2018-01-24T21:42:06.265030265Z Waiting for container to finish
2018-01-24T21:56:48.111470432Z Container exited with code: 0
2018-01-24T21:56:48.111744032Z Uploading ./ArrayMetric_GRS0004294.merged.txt (17 bytes)

Related issues

Related to Arvados - Story #13048: Refactor crunch2 loggingNew

History

#1 Updated by Tom Clegg 10 months ago

#2 Updated by Peter Amstutz 10 months ago

Very likely this is due to glibc buffering, which means crunch-run doesn't see the output until the program exits and flushes the output buffer.

Also available in: Atom PDF