stpipe behaves weirdly with loggers

[thomaswilliamsastro]

I'm currently trying to use my own logging and wrap around some of the JWST pipeline. This works OK, but the logs seem to produce multiple outputs once I've used anything that wraps around stpipe. I import a logger at the top of my submodule like :

log = logging.getLogger(__name__)

and then log.info('Test message') produces

[2023-06-29 14:28:39,968] pjpipe.download.download_step - INFO - Test message

as expected. However, after I open up a datamodel

im = datamodels.open(filename) log.info('Test message')

then produces 3 messages:

[2023-06-29 14:28:41,361] pjpipe.download.download_step - INFO - Test message
2023-06-29 14:28:41,361 - stpipe - INFO - Test message
[2023-06-29 14:28:41,361] stpipe - INFO - Test message

This doesn't seem like intended behaviour, and seems like it should be a relatively easy fix

[jdavies-st]

Related to issues discussed spacetelescope/jwst#4658

[jdavies-st]

So adding some more detail here, the logging in stpipe is a mess. It provides the stpipe logger as its base logger, but for example, the jwst package creates a bunch of its own loggers, and it's not clear which logger is emitting a particular log message, which makes it impossible to set per-log levels or do filtering or handling properly.

As an example, after running calwebb_detector1 and calwebb_image3, the created loggers are:

In [13]: import logging
    ...: 
    ...: loggers = [logging.getLogger(name) for name in logging.root.manager.loggerDict]

In [19]: logger_names = [l.name for l in loggers]

In [20]: logger_names.sort()

In [21]: logger_names
Out[21]: 
['CRDS',
 'Detector1Pipeline',
 'Image3Pipeline',
 'PIL',
 'PIL.Image',
 'PIL.PngImagePlugin',
 'TerminalIPythonApp',
 'TweakRegStep',
 'astropy',
 'asyncio',
 'charset_normalizer',
 'concurrent',
 'concurrent.futures',
 'crds',
 'crds.bestrefs',
 'crds.bestrefs.bestrefs',
 'filelock',
 'jwst',
 'jwst.ami',
 'jwst.ami.ami_analyze',
 'jwst.ami.ami_average',
 'jwst.ami.ami_normalize',
 'jwst.ami.analyticnrm2',
 'jwst.ami.find_affine2d_parameters',
 'jwst.ami.hexee',
 'jwst.ami.instrument_data',
 'jwst.ami.leastsqnrm',
 'jwst.ami.lg_model',
 'jwst.ami.nrm_core',
 'jwst.ami.utils',
 'jwst.assign_mtwcs',
 'jwst.assign_mtwcs.assign_mtwcs_step',
 'jwst.assign_mtwcs.moving_target_wcs',
 'jwst.assign_wcs',
 'jwst.assign_wcs.assign_wcs',
 'jwst.assign_wcs.assign_wcs_step',
 'jwst.assign_wcs.miri',
 'jwst.assign_wcs.nircam',
 'jwst.assign_wcs.niriss',
 'jwst.assign_wcs.nirspec',
 'jwst.assign_wcs.util',
 'jwst.associations',
 'jwst.associations.association',
 'jwst.associations.association_io',
 'jwst.associations.generator',
 'jwst.associations.generator.generate',
 'jwst.associations.lib',
 'jwst.associations.lib.constraint',
 'jwst.associations.lib.diff',
 'jwst.associations.lib.product_utils',
 'jwst.associations.lib.prune',
 'jwst.associations.lib.rules_level2_base',
 'jwst.associations.lib.rules_level3_base',
 'jwst.associations.lib.utilities',
 'jwst.associations.registry',
 'jwst.background',
 'jwst.background.background_sub',
 'jwst.background.subtract_images',
 'jwst.barshadow',
 'jwst.barshadow.bar_shadow',
 'jwst.charge_migration',
 'jwst.charge_migration.charge_migration',
 'jwst.charge_migration.charge_migration_step',
 'jwst.combine_1d',
 'jwst.combine_1d.combine1d',
 'jwst.coron',
 'jwst.coron.hlsp',
 'jwst.coron.imageregistration',
 'jwst.coron.klip',
 'jwst.coron.median_replace_img',
 'jwst.coron.stack_refs',
 'jwst.cube_build',
 'jwst.cube_build.cube_build',
 'jwst.cube_build.cube_build_io_util',
 'jwst.cube_build.cube_build_wcs_util',
 'jwst.cube_build.data_types',
 'jwst.cube_build.file_table',
 'jwst.cube_build.ifu_cube',
 'jwst.cube_build.instrument_defaults',
 'jwst.cube_skymatch',
 'jwst.cube_skymatch.skymatch',
 'jwst.datamodels',
 'jwst.datamodels.container',
 'jwst.dq_init',
 'jwst.dq_init.dq_initialization',
 'jwst.emicorr',
 'jwst.emicorr.emicorr',
 'jwst.exp_to_source',
 'jwst.exp_to_source.exp_to_source',
 'jwst.extract_1d',
 'jwst.extract_1d.extract',
 'jwst.extract_1d.extract1d',
 'jwst.extract_1d.ifu',
 'jwst.extract_1d.soss_extract',
 'jwst.extract_1d.soss_extract.atoca',
 'jwst.extract_1d.soss_extract.atoca_utils',
 'jwst.extract_1d.soss_extract.soss_boxextract',
 'jwst.extract_1d.soss_extract.soss_centroids',
 'jwst.extract_1d.soss_extract.soss_extract',
 'jwst.extract_1d.soss_extract.soss_solver',
 'jwst.extract_1d.soss_extract.soss_syscor',
 'jwst.extract_1d.soss_extract.soss_utils',
 'jwst.extract_1d.spec_wcs',
 'jwst.extract_2d',
 'jwst.extract_2d.extract_2d',
 'jwst.extract_2d.grisms',
 'jwst.extract_2d.nirspec',
 'jwst.firstframe',
 'jwst.firstframe.firstframe_sub',
 'jwst.flatfield',
 'jwst.flatfield.flat_field',
 'jwst.fringe',
 'jwst.fringe.fringe',
 'jwst.gain_scale',
 'jwst.gain_scale.gain_scale',
 'jwst.group_scale',
 'jwst.group_scale.group_scale',
 'jwst.guider_cds',
 'jwst.guider_cds.guider_cds',
 'jwst.guider_cds.guider_cds_step',
 'jwst.ipc',
 'jwst.ipc.ipc_corr',
 'jwst.jump',
 'jwst.jump.jump',
 'jwst.lastframe',
 'jwst.lastframe.lastframe_sub',
 'jwst.lib',
 'jwst.lib.dispaxis',
 'jwst.lib.progress',
 'jwst.lib.reffile_utils',
 'jwst.lib.signal_slot',
 'jwst.lib.suffix',
 'jwst.linearity',
 'jwst.linearity.linearity',
 'jwst.master_background',
 'jwst.master_background.expand_to_2d',
 'jwst.master_background.nirspec_utils',
 'jwst.mrs_imatch',
 'jwst.msaflagopen',
 'jwst.msaflagopen.msaflag_open',
 'jwst.nsclean',
 'jwst.nsclean.nsclean',
 'jwst.outlier_detection',
 'jwst.outlier_detection.outlier_detection',
 'jwst.outlier_detection.outlier_detection_ifu',
 'jwst.outlier_detection.outlier_detection_scaled',
 'jwst.outlier_detection.outlier_detection_spec',
 'jwst.pathloss',
 'jwst.pathloss.pathloss',
 'jwst.persistence',
 'jwst.persistence.persistence',
 'jwst.photom',
 'jwst.photom.miri_imager',
 'jwst.photom.miri_mrs',
 'jwst.photom.photom',
 'jwst.pipeline',
 'jwst.pipeline.calwebb_ami3',
 'jwst.pipeline.calwebb_dark',
 'jwst.pipeline.calwebb_detector1',
 'jwst.pipeline.calwebb_guider',
 'jwst.pixel_replace',
 'jwst.pixel_replace.pixel_replace',
 'jwst.ramp_fitting',
 'jwst.ramp_fitting.ramp_fit_step',
 'jwst.refpix',
 'jwst.refpix.irs2_subtract_reference',
 'jwst.refpix.reference_pixels',
 'jwst.resample',
 'jwst.resample.gwcs_drizzle',
 'jwst.resample.resample',
 'jwst.resample.resample_spec',
 'jwst.resample.resample_step',
 'jwst.resample.resample_utils',
 'jwst.reset',
 'jwst.reset.reset_sub',
 'jwst.residual_fringe',
 'jwst.residual_fringe.residual_fringe',
 'jwst.residual_fringe.utils',
 'jwst.rscd',
 'jwst.rscd.rscd_sub',
 'jwst.saturation',
 'jwst.saturation.saturation',
 'jwst.skymatch',
 'jwst.skymatch.skymatch',
 'jwst.source_catalog',
 'jwst.source_catalog.detection',
 'jwst.source_catalog.reference_data',
 'jwst.source_catalog.source_catalog',
 'jwst.spectral_leak',
 'jwst.spectral_leak.spectral_leak',
 'jwst.srctype',
 'jwst.srctype.srctype',
 'jwst.stpipe',
 'jwst.stpipe.core',
 'jwst.straylight',
 'jwst.straylight.straylight',
 'jwst.superbias',
 'jwst.superbias.bias_sub',
 'jwst.tso_photometry',
 'jwst.tso_photometry.tso_photometry',
 'jwst.tweakreg',
 'jwst.tweakreg.tweakreg_catalog',
 'jwst.wavecorr',
 'jwst.wavecorr.wavecorr',
 'jwst.wfs_combine',
 'jwst.wfs_combine.wfs_combine',
 'jwst.wfss_contam',
 'jwst.wfss_contam.observations',
 'jwst.wfss_contam.sens1d',
 'jwst.wfss_contam.wfss_contam',
 'jwst.white_light',
 'jwst.white_light.white_light',
 'matplotlib',
 'matplotlib._afm',
 'matplotlib._constrained_layout',
 'matplotlib._layoutgrid',
 'matplotlib.animation',
 'matplotlib.artist',
 'matplotlib.axes',
 'matplotlib.axes._axes',
 'matplotlib.axes._base',
 'matplotlib.axis',
 'matplotlib.backend_bases',
 'matplotlib.category',
 'matplotlib.colorbar',
 'matplotlib.dates',
 'matplotlib.dviread',
 'matplotlib.figure',
 'matplotlib.font_manager',
 'matplotlib.gridspec',
 'matplotlib.image',
 'matplotlib.lines',
 'matplotlib.mathtext',
 'matplotlib.pyplot',
 'matplotlib.style',
 'matplotlib.style.core',
 'matplotlib.texmanager',
 'matplotlib.text',
 'matplotlib.textpath',
 'matplotlib.ticker',
 'packaging',
 'packaging.tags',
 'parso',
 'parso.cache',
 'parso.python',
 'parso.python.diff',
 'pkg_resources',
 'pkg_resources.extern',
 'pkg_resources.extern.packaging',
 'pkg_resources.extern.packaging.tags',
 'poppy',
 'prompt_toolkit',
 'prompt_toolkit.buffer',
 'py',
 'py.warnings',
 'requests',
 'stack_data',
 'stack_data.serializing',
 'stcal',
 'stcal.dark_current',
 'stcal.dark_current.dark_sub',
 'stcal.jump',
 'stcal.jump.jump',
 'stcal.jump.twopoint_difference',
 'stcal.ramp_fitting',
 'stcal.ramp_fitting.gls_fit',
 'stcal.ramp_fitting.ols_fit',
 'stcal.ramp_fitting.ramp_fit',
 'stcal.ramp_fitting.utils',
 'stcal.saturation',
 'stcal.saturation.saturation',
 'stdatamodels',
 'stdatamodels.dynamicdq',
 'stdatamodels.fits_support',
 'stdatamodels.jwst',
 'stdatamodels.jwst.datamodels',
 'stdatamodels.jwst.datamodels.util',
 'stdatamodels.properties',
 'stdatamodels.util',
 'stpipe',
 'stpipe.Detector1Pipeline',
 'stpipe.Detector1Pipeline.charge_migration',
 'stpipe.Detector1Pipeline.dark_current',
 'stpipe.Detector1Pipeline.dq_init',
 'stpipe.Detector1Pipeline.emicorr',
 'stpipe.Detector1Pipeline.firstframe',
 'stpipe.Detector1Pipeline.gain_scale',
 'stpipe.Detector1Pipeline.group_scale',
 'stpipe.Detector1Pipeline.ipc',
 'stpipe.Detector1Pipeline.jump',
 'stpipe.Detector1Pipeline.lastframe',
 'stpipe.Detector1Pipeline.linearity',
 'stpipe.Detector1Pipeline.persistence',
 'stpipe.Detector1Pipeline.ramp_fit',
 'stpipe.Detector1Pipeline.refpix',
 'stpipe.Detector1Pipeline.reset',
 'stpipe.Detector1Pipeline.rscd',
 'stpipe.Detector1Pipeline.saturation',
 'stpipe.Detector1Pipeline.superbias',
 'stpipe.Image3Pipeline',
 'stpipe.Image3Pipeline.assign_mtwcs',
 'stpipe.Image3Pipeline.outlier_detection',
 'stpipe.Image3Pipeline.resample',
 'stpipe.Image3Pipeline.skymatch',
 'stpipe.Image3Pipeline.source_catalog',
 'stpipe.Image3Pipeline.tweakreg',
 'stpipe.config_parser',
 'stpipe.tweakreg',
 'tweakwcs',
 'tweakwcs.correctors',
 'tweakwcs.imalign',
 'tweakwcs.linalg',
 'tweakwcs.linearfit',
 'tweakwcs.matchutils',
 'tweakwcs.wcsimage',
 'urllib3',
 'urllib3.connection',
 'urllib3.connectionpool',
 'urllib3.poolmanager',
 'urllib3.response',
 'urllib3.util',
 'urllib3.util.retry']

And as you can see, jwst and stpipe seem to be creating loggers for the same classes and modules.

And the problem is that stpipe scoops up all log messages, and applies format for all these loggers, not just the ones from stpipe or downstream to jwst, for example. This is a pattern to avoid.

And, stpipe itself keeps a instance variable internally pointed to the log singleton(s), another pattern to avoid, as each logger is global.

[schlafly]

This also affects romanisim, which doesn't really use stpipe but which inherits it from some other dependency---presumably somehow through datamodel usage?

2024-07-15 13:33:29 INFO Adding sources to image...
2024-07-15 13:33:29,322 - stpipe - INFO - Adding sources to image...
2024-07-15 13:33:29 INFO Adding sources to image...