Open thomaswilliamsastro opened 1 year ago
Related to issues discussed https://github.com/spacetelescope/jwst/issues/4658
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.
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...
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')
producesas expected. However, after I open up a datamodel
im = datamodels.open(filename) log.info('Test message')
then produces 3 messages:
This doesn't seem like intended behaviour, and seems like it should be a relatively easy fix