8000 stpipe behaves weirdly with loggers · Issue #96 · spacetelescope/stpipe · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

stpipe behaves weirdly with loggers #96

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
thomaswilliamsastro opened this issue Jun 29, 2023 · 3 comments
Open

stpipe behaves weirdly with loggers #96

thomaswilliamsastro opened this issue Jun 29, 2023 · 3 comments

Comments

@thomaswilliamsastro
Copy link
thomaswilliamsastro commented Jun 29, 2023 •
edited
Loading

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
Copy link
Contributor

Related to issues discussed spacetelescope/jwst#4658

@jdavies-st
Copy link
Contributor
jdavies-st commented Mar 1, 2024 •
edited
Loading
8000

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
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@schlafly @jdavies-st @thomaswilliamsastro
0