Uploaded image for project: 'Data Management'
  1. Data Management
  2. DM-4342

Disentangle log messages from different processes

    Details

    • Type: Story
    • Status: Done
    • Resolution: Done
    • Fix Version/s: None
    • Component/s: pex_logging, pipe_base
    • Labels:
      None

      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:
      • Chain logs of sub-tasks to their parent task logs
      • 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
        

        Attachments

          Issue Links

            Activity

            Hide
            hchiang2 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
            hchiang2 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
            price Paul Price added a comment -

            Very nice, thanks.

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

            Show
            price Paul Price added a comment - Very nice, thanks. I've made a few comments on the github PRs, but nothing major.
            Hide
            hchiang2 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
            hchiang2 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
            hchiang2 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
            hchiang2 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
            hchiang2 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:
                hchiang2 Hsin-Fang Chiang
                Reporter:
                price 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
              • Votes:
                0 Vote for this issue
                Watchers:
                10 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Summary Panel