If you want to replace Task.log with a Python logger (which seems like the cleanest outcome) this will likely require some tweaking of existing tasks, as some methods are a bit different. For instance Python logging has no methods with "f" suffixes, e.g. infof, at least that I can find in the docs (though I doubt we are using those widely yet). I also expect some changes to unit tests and possibly bin scripts that adjust logging levels.

Still that does seem cleaner than trying to provide backwards compatibility with a new task attribute that holds a new style log.

I am willing to implement this change, or help with the implementation.

I think the outcome is meant to be that if one of our python packages uses logging (for example daf_butler, which is what triggered this) and that usage of logging is entirely internal (ie it doesn't make available a logger to be used externally) then those log messages should be forwarded to the standard LSST logger when that package is used within a science pipelines application. So I don't think this means changing code that already uses lsst.log – it allows packages to use logging for a more pythonic interface if they wish (and I think new pytest understands python logging now). The proposal is to register a handler with logging that results in those log messages being forwarded to lsst.log behind the scenes. pipe_base would register the log handler and tell python logging to use DEBUG level to ensure all messages are forwarded to the LSST logger for filtering. I have no idea how named loggers interact with the scheme and whether there is an implication that for this to work the packages using python logging must use the root logger.

This logging issue came up in DM-17530. As we start to integrate astro_metadata_translator and daf_butler into tasks it's going to become more important for tasks to receive python logging messages. Andy Salnikov, Jim Bosch is it much work to tweak PipelineTask and CmdLineTask to enable this forwarding?

I'm afraid you know as much about this as I do (probably more).

It has been done already for PipelineTask (https://github.com/lsst/ctrl_mpexec/blob/master/python/lsst/ctrl/mpexec/cmdLineFwk.py#L171-L174). I can add the same to CmdLineTask but I need somehow to validate that it works. Is there a simple CmdLineTask that I could use as a test with gen3 butler?
I also saw some peculiar behavior with forwarding which looked unexpected to me at that time, I can probably investigate that at the same time. Assigning ticket to myself.

Thank you for adding this to PipelineTask!

Andy Salnikov DM-17530 shows how to reproduce it using obs_lsst (which isn't yet in the weekly build) since astro_metadata_translator issues warnings.

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).

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'

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.

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

Merged.