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

Forward python logging to lsst.log in pipe_base

    Details

    • Story Points:
      1
    • Sprint:
      BG3_S19_01
    • Team:
      Data Access and Database

      Description

      In RFC-29 we allowed Python logging to be used in Python code so long as the log messages were forwarded to lsst.log whenever C++ logging is a possibility. A forwarder does exist as lsst.log.LogHandler and instructions for its use are available at https://github.com/lsst/log/blob/master/doc/mainpage.dox#L59

      To enable science pipelines to forward these Python log messages we need to setup this log handler in pipe_base.

        Attachments

          Activity

          Hide
          salnikov Andy Salnikov added a comment - - edited

          Re "peculiar behavior" - that comes from non-trivial interaction between python logging and lsst.log LogContext thing. lsst.log has a Logging Contexts idea which is a sort of a stack of logger names pushed an popped by the client code. Current logging context defines the name of a default logger which is a logger used when you do not provide your own logger name. I think that whole thing is misguided and it is probably a heritage of the old logging system, but anyways it is there. In C++ code you can push/pop names using special macros or using more exception-safe RAII class LogContext(string name). In Python land there is a context manager class with the same name but slightly different functionality - in addition to managing context stack it can also change logging level for that default handler which is on the top of the stack (plus it has few extra methods to set/check logging level of the default handler).

          LogContext can be used for different purposes:

              # temporarily push logger name (w.r.t. current default logger name)
              with LogContext(name="myLogger"):
                  lsst.log.info("Log info record using (relative) myLogger logger")
           
              # temporarily change logging level of default logger
              with LogContext(level=lsst.log.DEBUG):
                  lsst.log.debug("Log debug record using default logger")
           
              # can also combine both
              with LogContext(name="myLogger", level=lsst.log.DEBUG):
                  # ....
          

          The LogHandler Python class is a logging.Handler implementation which forwards Python logging records to lsst.log loggers. You can instantiate this handler and attach it to Python logger in a regular way:

              logging.getLogger().addHandler(lsst.log.LogHandler()) # attach to a root logger
              logging.getLogger("dax.db").addHandler(lsst.log.LogHandler()) # attach to a "dax.db" logger
          

          (we do former in ctrl_mpexec)

          LogHandler does some checks/transforms before forwarding records lsst.log and its implementation uses LogContext internally for those checks (and it takes the same parameters as LogContext) which confuses things. Before forwarding message to lsst.log LogHandler checks logging level in the current context (meaning current default logger which may be different from a context that was used in creating LogHandler). this is where the issues pop up - if python logs to a logger with a name "dax.db" for example and it propagates to a logging root logger (if no one messes up logging configuration) then LogHandler gets this message and checks its level against default lsst.log logger which is a root logger and forwards it to "dax.db" lsst.log logger. If lsst.log is configured so that level of root logger is INFO and "dax.db" level is DEBUG then DEBUG message will not be forwarded. This is what I observe with pipetask.

          It should be relatively easy to fix but this context thing messes things up big time. I think we should get rid of it entirely, I searched lsst repos and no one is using this context "feature bug" (people a not as crazy aw we though). I'll open a next ticket for it (maybe RFC is needed first).

          Show
          salnikov Andy Salnikov added a comment - - edited Re "peculiar behavior" - that comes from non-trivial interaction between python logging and lsst.log LogContext thing. lsst.log has a Logging Contexts idea which is a sort of a stack of logger names pushed an popped by the client code. Current logging context defines the name of a default logger which is a logger used when you do not provide your own logger name. I think that whole thing is misguided and it is probably a heritage of the old logging system, but anyways it is there. In C++ code you can push/pop names using special macros or using more exception-safe RAII class LogContext(string name) . In Python land there is a context manager class with the same name but slightly different functionality - in addition to managing context stack it can also change logging level for that default handler which is on the top of the stack (plus it has few extra methods to set/check logging level of the default handler). LogContext can be used for different purposes: # temporarily push logger name (w.r.t. current default logger name) with LogContext(name = "myLogger" ): lsst.log.info( "Log info record using (relative) myLogger logger" )   # temporarily change logging level of default logger with LogContext(level = lsst.log.DEBUG): lsst.log.debug( "Log debug record using default logger" )   # can also combine both with LogContext(name = "myLogger" , level = lsst.log.DEBUG): # .... The LogHandler Python class is a logging.Handler implementation which forwards Python logging records to lsst.log loggers. You can instantiate this handler and attach it to Python logger in a regular way: logging.getLogger().addHandler(lsst.log.LogHandler()) # attach to a root logger logging.getLogger( "dax.db" ).addHandler(lsst.log.LogHandler()) # attach to a "dax.db" logger (we do former in ctrl_mpexec ) LogHandler does some checks/transforms before forwarding records lsst.log and its implementation uses LogContext internally for those checks (and it takes the same parameters as LogContext ) which confuses things. Before forwarding message to lsst.log LogHandler checks logging level in the current context (meaning current default logger which may be different from a context that was used in creating LogHandler). this is where the issues pop up - if python logs to a logger with a name "dax.db" for example and it propagates to a logging root logger (if no one messes up logging configuration) then LogHandler gets this message and checks its level against default lsst.log logger which is a root logger and forwards it to "dax.db" lsst.log logger. If lsst.log is configured so that level of root logger is INFO and "dax.db" level is DEBUG then DEBUG message will not be forwarded. This is what I observe with pipetask . It should be relatively easy to fix but this context thing messes things up big time. I think we should get rid of it entirely, I searched lsst repos and no one is using this context "feature bug" (people a not as crazy aw we though). I'll open a next ticket for it (maybe RFC is needed first).
          Hide
          salnikov Andy Salnikov added a comment -

          Tim, sorry it longer than I expected - it uncovered some interesting issues in lsst.log that we did not expect  Should be ready for review, and I started Jenkins build to see how much it is going to break. ingestImages now produces messages like these:

          root INFO: Loading config overrride file '/project/salnikov/gen3-middleware/obs_lsst/config/ingest.py'
          root INFO: Loading config overrride file '/project/salnikov/gen3-middleware/obs_lsst/config/auxTel/ingest.py'
          LsstCamMapper WARN: Unable to find valid calib root directory
          CameraMapper INFO: Loading exposure registry from /project/salnikov/gen3-middleware/obs_lsst/DM-17530_repo/registry.sqlite3
          astro_metadata_translator.observationInfo WARN: OrderedDict([('SIMPLE', True), ('BITPIX', 8), ('NAXIS', 0), ('EXTEND', True), ('ORIGIN', 'BNL'), ('DATE', '2016-07-21T02:17:33.872'), ('DATE-OBS', '2016-07-21T02:17:30.700'), ('MJD-OBS', 57590.09549421305), ('IMAGETAG', 'CCS'), ('TSTAND', 'BNL-TS3-2-Janeway'), ('INSTRUME', 'ArchonCCDController'), ('CONTROLL', 'ArchonCCDController'), ('CCD_MANU', 'ITL'), ('CCD_TYPE', 'STA3800C'), ('CCD_SERN', 'ITL-3800C-098'), ('LSST_NUM', 'ITL-3800C-098'), ('TESTTYPE', 'DARK'), ('IMGTYPE', 'BIAS'), ('SEQNUM', 0), ('TEMP_SET', -95.0), ('CCDTEMP', -94.58139), ('CCDBSS', -35.0), ('MONDIODE', -0.5529727999999999), ('MONOWL', -1.0), ('PIXRATE', 549.4505494505494), ('FILTER', '550CutOn'), ('FILTPOS', 3), ('EXPTIME', 0.0), ('CTLRCFG', 'bnl_STA_20160718_B.acf'), ('FILENAME', 'ITL-3800C-098_dark_bias_000_20160720221733.fits'), ('DETSIZE', '[1:4072,1:4000]'), ('BINX', 1), ('BINY', 1), ('HEADVER', 1), ('CCDGAIN', 4.5), ('CCDNOISE', 1.0), ('CFGFILE', 'bnl_STA_20160718_B.acf'), ('CTLRID', '23723640293011484'), ('CTLRRV', 3), ('CTLRTYP', 1), ('CTLRVER', '1.0.762'), ('MONOCH-WAVELENG', 500.015), ('MONOCH-SLIT_A', 210.0), ('MONOCH-SLIT_B', 210.0), ('MONOCH-SLIT_C', 0.0), ('MONOCH-BANDPASS', 0.0), ('MONOCH-FILT_1', 3.0), ('MONOCH-MSTEPS', 1200.0), ('MONOCH-GRATING', 1.0), ('AMP0-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP0-AZERO', 'F'), ('AMP0-COUNT', 440), ('AMP0-MEAS_NPLC', 1), ('AMP2-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP2-VOLTAGE', -35.0), ('AMP2-CURRENT', -117754.1), ('AMP2-ZERO_CHECK', 'off'), ('CHECKSUM', 'nmkBnmjBnmjBnmjB'), ('DATASUM', '0')])
          astro_metadata_translator.observationInfo WARN: Error calculating property 'exposure_id' using translator <class 'lsst.obs.lsst.translators.auxTel.LsstAuxTelTranslator'>: 'DAYOBS'
          astro_metadata_translator.observationInfo WARN: OrderedDict([('SIMPLE', True), ('BITPIX', 8), ('NAXIS', 0), ('EXTEND', True), ('ORIGIN', 'BNL'), ('DATE', '2016-07-21T02:17:33.872'), ('DATE-OBS', '2016-07-21T02:17:30.700'), ('MJD-OBS', 57590.09549421305), ('IMAGETAG', 'CCS'), ('TSTAND', 'BNL-TS3-2-Janeway'), ('INSTRUME', 'ArchonCCDController'), ('CONTROLL', 'ArchonCCDController'), ('CCD_MANU', 'ITL'), ('CCD_TYPE', 'STA3800C'), ('CCD_SERN', 'ITL-3800C-098'), ('LSST_NUM', 'ITL-3800C-098'), ('TESTTYPE', 'DARK'), ('IMGTYPE', 'BIAS'), ('SEQNUM', 0), ('TEMP_SET', -95.0), ('CCDTEMP', -94.58139), ('CCDBSS', -35.0), ('MONDIODE', -0.5529727999999999), ('MONOWL', -1.0), ('PIXRATE', 549.4505494505494), ('FILTER', '550CutOn'), ('FILTPOS', 3), ('EXPTIME', 0.0), ('CTLRCFG', 'bnl_STA_20160718_B.acf'), ('FILENAME', 'ITL-3800C-098_dark_bias_000_20160720221733.fits'), ('DETSIZE', '[1:4072,1:4000]'), ('BINX', 1), ('BINY', 1), ('HEADVER', 1), ('CCDGAIN', 4.5), ('CCDNOISE', 1.0), ('CFGFILE', 'bnl_STA_20160718_B.acf'), ('CTLRID', '23723640293011484'), ('CTLRRV', 3), ('CTLRTYP', 1), ('CTLRVER', '1.0.762'), ('MONOCH-WAVELENG', 500.015), ('MONOCH-SLIT_A', 210.0), ('MONOCH-SLIT_B', 210.0), ('MONOCH-SLIT_C', 0.0), ('MONOCH-BANDPASS', 0.0), ('MONOCH-FILT_1', 3.0), ('MONOCH-MSTEPS', 1200.0), ('MONOCH-GRATING', 1.0), ('AMP0-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP0-AZERO', 'F'), ('AMP0-COUNT', 440), ('AMP0-MEAS_NPLC', 1), ('AMP2-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP2-VOLTAGE', -35.0), ('AMP2-CURRENT', -117754.1), ('AMP2-ZERO_CHECK', 'off'), ('CHECKSUM', 'nmkBnmjBnmjBnmjB'), ('DATASUM', '0')])
          astro_metadata_translator.observationInfo WARN: Error calculating property 'visit_id' using translator <class 'lsst.obs.lsst.translators.auxTel.LsstAuxTelTranslator'>: 'DAYOBS'
          lsst.obs.lsst.translators.auxTel WARN: Unable to determine observation type. Guessing 'bias'
           

          Show
          salnikov Andy Salnikov added a comment - Tim, sorry it longer than I expected - it uncovered some interesting issues in lsst.log that we did not expect  Should be ready for review, and I started Jenkins build to see how much it is going to break. ingestImages now produces messages like these: root INFO: Loading config overrride file '/project/salnikov/gen3-middleware/obs_lsst/config/ingest.py' root INFO: Loading config overrride file '/project/salnikov/gen3-middleware/obs_lsst/config/auxTel/ingest.py' LsstCamMapper WARN: Unable to find valid calib root directory CameraMapper INFO: Loading exposure registry from /project/salnikov/gen3-middleware/obs_lsst/DM-17530_repo/registry.sqlite3 astro_metadata_translator.observationInfo WARN: OrderedDict([('SIMPLE', True), ('BITPIX', 8), ('NAXIS', 0), ('EXTEND', True), ('ORIGIN', 'BNL'), ('DATE', '2016-07-21T02:17:33.872'), ('DATE-OBS', '2016-07-21T02:17:30.700'), ('MJD-OBS', 57590.09549421305), ('IMAGETAG', 'CCS'), ('TSTAND', 'BNL-TS3-2-Janeway'), ('INSTRUME', 'ArchonCCDController'), ('CONTROLL', 'ArchonCCDController'), ('CCD_MANU', 'ITL'), ('CCD_TYPE', 'STA3800C'), ('CCD_SERN', 'ITL-3800C-098'), ('LSST_NUM', 'ITL-3800C-098'), ('TESTTYPE', 'DARK'), ('IMGTYPE', 'BIAS'), ('SEQNUM', 0), ('TEMP_SET', -95.0), ('CCDTEMP', -94.58139), ('CCDBSS', -35.0), ('MONDIODE', -0.5529727999999999), ('MONOWL', -1.0), ('PIXRATE', 549.4505494505494), ('FILTER', '550CutOn'), ('FILTPOS', 3), ('EXPTIME', 0.0), ('CTLRCFG', 'bnl_STA_20160718_B.acf'), ('FILENAME', 'ITL-3800C-098_dark_bias_000_20160720221733.fits'), ('DETSIZE', '[1:4072,1:4000]'), ('BINX', 1), ('BINY', 1), ('HEADVER', 1), ('CCDGAIN', 4.5), ('CCDNOISE', 1.0), ('CFGFILE', 'bnl_STA_20160718_B.acf'), ('CTLRID', '23723640293011484'), ('CTLRRV', 3), ('CTLRTYP', 1), ('CTLRVER', '1.0.762'), ('MONOCH-WAVELENG', 500.015), ('MONOCH-SLIT_A', 210.0), ('MONOCH-SLIT_B', 210.0), ('MONOCH-SLIT_C', 0.0), ('MONOCH-BANDPASS', 0.0), ('MONOCH-FILT_1', 3.0), ('MONOCH-MSTEPS', 1200.0), ('MONOCH-GRATING', 1.0), ('AMP0-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP0-AZERO', 'F'), ('AMP0-COUNT', 440), ('AMP0-MEAS_NPLC', 1), ('AMP2-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP2-VOLTAGE', -35.0), ('AMP2-CURRENT', -117754.1), ('AMP2-ZERO_CHECK', 'off'), ('CHECKSUM', 'nmkBnmjBnmjBnmjB'), ('DATASUM', '0')]) astro_metadata_translator.observationInfo WARN: Error calculating property 'exposure_id' using translator <class 'lsst.obs.lsst.translators.auxTel.LsstAuxTelTranslator'>: 'DAYOBS' astro_metadata_translator.observationInfo WARN: OrderedDict([('SIMPLE', True), ('BITPIX', 8), ('NAXIS', 0), ('EXTEND', True), ('ORIGIN', 'BNL'), ('DATE', '2016-07-21T02:17:33.872'), ('DATE-OBS', '2016-07-21T02:17:30.700'), ('MJD-OBS', 57590.09549421305), ('IMAGETAG', 'CCS'), ('TSTAND', 'BNL-TS3-2-Janeway'), ('INSTRUME', 'ArchonCCDController'), ('CONTROLL', 'ArchonCCDController'), ('CCD_MANU', 'ITL'), ('CCD_TYPE', 'STA3800C'), ('CCD_SERN', 'ITL-3800C-098'), ('LSST_NUM', 'ITL-3800C-098'), ('TESTTYPE', 'DARK'), ('IMGTYPE', 'BIAS'), ('SEQNUM', 0), ('TEMP_SET', -95.0), ('CCDTEMP', -94.58139), ('CCDBSS', -35.0), ('MONDIODE', -0.5529727999999999), ('MONOWL', -1.0), ('PIXRATE', 549.4505494505494), ('FILTER', '550CutOn'), ('FILTPOS', 3), ('EXPTIME', 0.0), ('CTLRCFG', 'bnl_STA_20160718_B.acf'), ('FILENAME', 'ITL-3800C-098_dark_bias_000_20160720221733.fits'), ('DETSIZE', '[1:4072,1:4000]'), ('BINX', 1), ('BINY', 1), ('HEADVER', 1), ('CCDGAIN', 4.5), ('CCDNOISE', 1.0), ('CFGFILE', 'bnl_STA_20160718_B.acf'), ('CTLRID', '23723640293011484'), ('CTLRRV', 3), ('CTLRTYP', 1), ('CTLRVER', '1.0.762'), ('MONOCH-WAVELENG', 500.015), ('MONOCH-SLIT_A', 210.0), ('MONOCH-SLIT_B', 210.0), ('MONOCH-SLIT_C', 0.0), ('MONOCH-BANDPASS', 0.0), ('MONOCH-FILT_1', 3.0), ('MONOCH-MSTEPS', 1200.0), ('MONOCH-GRATING', 1.0), ('AMP0-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP0-AZERO', 'F'), ('AMP0-COUNT', 440), ('AMP0-MEAS_NPLC', 1), ('AMP2-IDN', 'KEITHLEY-INSTRUMENTS-INC.,MODEL-6487'), ('AMP2-VOLTAGE', -35.0), ('AMP2-CURRENT', -117754.1), ('AMP2-ZERO_CHECK', 'off'), ('CHECKSUM', 'nmkBnmjBnmjBnmjB'), ('DATASUM', '0')]) astro_metadata_translator.observationInfo WARN: Error calculating property 'visit_id' using translator <class 'lsst.obs.lsst.translators.auxTel.LsstAuxTelTranslator'>: 'DAYOBS' lsst.obs.lsst.translators.auxTel WARN: Unable to determine observation type. Guessing 'bias'
          Hide
          tjenness Tim Jenness added a comment -

          I don't understand a lot of the intricacies but the changes look good to me. The new output looks great and will really help a lot. Thank you. Merlin Fisher-Levine will be very happy with this change.

          Show
          tjenness Tim Jenness added a comment - I don't understand a lot of the intricacies but the changes look good to me. The new output looks great and will really help a lot. Thank you. Merlin Fisher-Levine will be very happy with this change.
          Hide
          salnikov Andy Salnikov added a comment -

          Thanks for review! It built successfully on centos6/7, still in queue for osx. I'm going to declare success and merge both packages.

          Show
          salnikov Andy Salnikov added a comment - Thanks for review! It built successfully on centos6/7, still in queue for osx. I'm going to declare success and merge both packages.
          Hide
          salnikov Andy Salnikov added a comment -

          Merged.

          Show
          salnikov Andy Salnikov added a comment - Merged.

            People

            • Assignee:
              salnikov Andy Salnikov
              Reporter:
              tjenness Tim Jenness
              Reviewers:
              Tim Jenness
              Watchers:
              Andy Salnikov, Jim Bosch, Kian-Tat Lim, Russell Owen, Tim Jenness
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Summary Panel