# Disentangle log messages from different processes

XMLWordPrintable

## Details

• Type: Story
• Status: Done
• Resolution: Done
• Fix Version/s: None
• Component/s:
• Labels:
None
• Story Points:
12
• Team:
Data Facility

## Description

It's difficult to disentangle interleaved log messages when running with multiprocessing. Two possible ways to do this would be:
1. Have each process write to a different log file. Maybe we could allow the user to specify log filenames including %(pid)s and %(hostname)s. More useful would be to allow the full range of keys from a dataId, but that might require some changes in how processing runs.
2. Prepend each line of the log with context information (dataId, pid, hostname), allowing the user to use grep to do the disentangling. To avoid overwhelming the log with the context information, a hash of the context information could be used instead, with the lookups published in the log before the processing starts.

##### Brief summary on the changes:
• Add PrependedFormatter as the new default formatter for log files (specified through --logdest command line argument for cmdLineTask). The standard output to the terminal remains the same as before.
• Any string can be used to label a pex_logging Log, and with PrependedFormatter this label prepends each log message. For cmdLineTask, the dataId is prepended.
• The HSC's commit on prepending the timestamps is also ported to PrependedFormatter.
• An example log message:

 2016-03-08T22:29:56.889933: [{'filter': 'r', 'tract': 0, 'patch': '2,3'}]: mergeCoaddDetections: Culled 1731 of 7751 peaks 

## Activity

Hide
Hsin-Fang Chiang added a comment -

KT pointed out that fractional second information can be useful for timing. So I rebased branch tickets/DM-4342 to leave out the HSC'c commit "eliminate digits after the decimal point of timestamp in logs". Then the log messages look like this:

 2016-03-07T14:56:01.531431: {'filter': 'r', 'visit': 257460, 'ccdnum': 1, 'tract': 0}: forcedPhotCcd.references: Getting references in region with corners ((352.82, 1.0434)), ((352.82, 0.89423)), ((353.11, 0.89351)), ((353.11, 1.0427)) [degrees] 

The branch including that commit is temporarily stored at u/hfc/DM-4342.

Show
Hsin-Fang Chiang added a comment - KT pointed out that fractional second information can be useful for timing. So I rebased branch tickets/ DM-4342 to leave out the HSC'c commit "eliminate digits after the decimal point of timestamp in logs". Then the log messages look like this: 2016 - 03 -07T14: 56 : 01.531431 : { 'filter' : 'r' , 'visit' : 257460 , 'ccdnum' : 1 , 'tract' : 0 }: forcedPhotCcd.references: Getting references in region with corners (( 352.82 , 1.0434 )), (( 352.82 , 0.89423 )), (( 353.11 , 0.89351 )), (( 353.11 , 1.0427 )) [degrees] The branch including that commit is temporarily stored at u/hfc/ DM-4342 .
Hide
Paul Price added a comment -

Very nice, thanks.

I've made a few comments on the github PRs, but nothing major.

Show
Paul Price added a comment - Very nice, thanks. I've made a few comments on the github PRs, but nothing major.
Hide
Hsin-Fang Chiang added a comment -

Thank you Paul Price.

Corrections on the coding style are done, and the range-based for loops are now used in LogFormatter.

I'll run Jenkins before merging.

Show
Hsin-Fang Chiang added a comment - Thank you Paul Price . Corrections on the coding style are done, and the range-based for loops are now used in LogFormatter. I'll run Jenkins before merging.
Hide
Hsin-Fang Chiang added a comment -
Show
Hsin-Fang Chiang added a comment - Jenkins lsst_distrib https://ci.lsst.codes/job/stack-os-matrix/label=centos-7/9007//console Jenkins ci_hsc https://ci.lsst.codes/job/stack-os-matrix/label=centos-7/9009//console
Hide
Hsin-Fang Chiang added a comment -

Changes in pex_logging and pipe_base are merged to master.

Many thanks to KT and Paul for the ideas and the tips to improve.

Show
Hsin-Fang Chiang added a comment - Changes in pex_logging and pipe_base are merged to master. Many thanks to KT and Paul for the ideas and the tips to improve.

## People

• Assignee:
Hsin-Fang Chiang
Reporter:
Paul Price
Reviewers:
Paul Price
Watchers:
Andy Salnikov, David Nidever [X] (Inactive), Hsin-Fang Chiang, Jacek Becla, John Swinbank, Kian-Tat Lim, Margaret Gelman, Paul Price, Robert Lupton, Russell Owen