[DM-15201] Forward python logging to lsst.log in pipe_base - Jira

Details

Type: Story
Status: Done
Resolution: Done
Fix Version/s: None
Component/s: pipe_base
Labels:
- SciencePipelines

Story Points:
1
Epic Link:
S19 PipelineTask
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

Ascending order - Click to sort in descending order

6 older comments

Hide

Permalink

Andy Salnikov added a comment - 29/Jan/19 12:04 PM - 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

Andy Salnikov added a comment - 29/Jan/19 12:04 PM - 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

Permalink

Andy Salnikov added a comment - 29/Jan/19 4:10 PM

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

Andy Salnikov added a comment - 29/Jan/19 4:10 PM 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

Permalink

Tim Jenness added a comment - 29/Jan/19 4:12 PM

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

Tim Jenness added a comment - 29/Jan/19 4:12 PM 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

Permalink

Andy Salnikov added a comment - 29/Jan/19 7:56 PM

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

Andy Salnikov added a comment - 29/Jan/19 7:56 PM 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

Permalink

Andy Salnikov added a comment - 29/Jan/19 7:58 PM

Merged.

Show

Andy Salnikov added a comment - 29/Jan/19 7:58 PM Merged.

Data Management

Forward python logging to lsst.log in pipe_base

Details

Description

Attachments

Activity

People

Dates

Jenkins