search

spacetelescope / jwst

Python library for science observations from the James Webb Space Telescope
https://jwst-pipeline.readthedocs.io/en/latest/
Other
570 stars 167 forks source link

remove MultilineLogger #8694

Closed braingram closed 3 months ago

braingram commented 3 months ago

This PR removes MultilineLogger

This logger splits log messages containing a newline character into multiple log messages. It also is sometimes registered as the default logger (only when jwst.associations.lib.log_config is imported). This produces unexpected changes in the test behavior that sometimes leads to test failures like the following in stcal: https://github.com/spacetelescope/stcal/actions/runs/10166472093/job/28116723217#step:10:3648 and as reported by external users: https://github.com/spacetelescope/jwst/issues/6407

The class and the registering of the class as the default logger occurred in the "initial commit" 8 years ago: https://github.com/spacetelescope/jwst/commit/5915b0e919be1e3393fd0ba74ff9106de77a4a1e

and I suspect contributes to other logging issues.

Regression tests all passed: https://plwishmaster.stsci.edu:8081/job/RT/job/JWST-Developers-Pull-Requests/1635/

Fixes https://github.com/spacetelescope/jwst/issues/6407

This is an alternative to https://github.com/spacetelescope/jwst/pull/7616

Checklist for PR authors (skip items if you don't have permissions or they are not applicable)

codecov[bot] commented 3 months ago

Codecov Report

Attention: Patch coverage is 44.44444% with 5 lines in your changes missing coverage. Please review.

Project coverage is 60.36%. Comparing base (f6c4095) to head (3ea0fa8). Report is 1 commits behind head on master.

Files Patch % Lines
jwst/dark_current/dark_current_step.py 0.00% 2 Missing :warning:
jwst/pixel_replace/pixel_replace_step.py 0.00% 2 Missing :warning:
jwst/scripts/set_telescope_pointing.py 0.00% 1 Missing :warning:
Additional details and impacted files ```diff @@ Coverage Diff @@ ## master #8694 +/- ## ========================================== - Coverage 60.38% 60.36% -0.02% ========================================== Files 372 372 Lines 38337 38324 -13 ========================================== - Hits 23148 23134 -14 - Misses 15189 15190 +1 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

melanieclarke commented 3 months ago

Do you know of any places where log messages contain newlines? I'm wondering how this will impact the log appearance.

braingram commented 3 months ago

I've so far only found 3 places (some of these files have multiple logging calls that contain a newline):

To use the pixel replace code as an example. Running the following:

import jwst.pixel_replace
s = jwst.pixel_replace.PixelReplaceStep(skip=False)
s(jwst.datamodels.AmiLgModel())  # giving this a unsupported model to trigger the log message

produces the following on main:

2024-08-07 16:59:42,940 - stpipe.PixelReplaceStep - ERROR - Input is of type <class 'stdatamodels.jwst.datamodels.amilg.AmiLgModel'> for which
2024-08-07 16:59:42,940 - stpipe.PixelReplaceStep - ERROR - pixel_replace does not have an algorithm.
2024-08-07 16:59:42,940 - stpipe.PixelReplaceStep - ERROR -
2024-08-07 16:59:42,940 - stpipe.PixelReplaceStep - ERROR - Pixel replacement will be skipped.

and the following with this PR:

2024-08-07 17:01:06,908 - stpipe.PixelReplaceStep - ERROR - Input is of type <class 'stdatamodels.jwst.datamodels.amilg.AmiLgModel'> for which
2024-08-07 17:01:06,908 - stpipe.PixelReplaceStep - ERROR - pixel_replace does not have an algorithm.

2024-08-07 17:01:06,908 - stpipe.PixelReplaceStep - ERROR - Pixel replacement will be skipped.
2024-08-07 17:01:06,908 - stpipe.PixelReplaceStep - INFO - Step PixelReplaceStep done

Looking at the newline containing log messages they could all be either removed (as the one above looks like a bug) or replaced by multiple logging calls (if multiple messages are expected).

melanieclarke commented 3 months ago

Okay, thanks. Can we add those fixes to this PR?

braingram commented 3 months ago

@melanieclarke I found a few more all of which should be fixed in 3ea0fa86a40e7038c9d5ca3bcbc071fee82d8cba

melanieclarke commented 3 months ago

I see a few more - in assign_wcs, extract, extract_1d, lib/set_telescope_pointing, stp_v1, calwebb_spec2, scripts/adjust_wcs, and tweakreg_step.

braingram commented 3 months ago

Can you provide links?

melanieclarke commented 3 months ago

I was searching offline, so it will take me a few minutes to cross-match to GitHub. I'll add them here as I pull them up.

https://github.com/spacetelescope/jwst/blob/3ea0fa86a40e7038c9d5ca3bcbc071fee82d8cba/jwst/assign_wcs/assign_wcs_step.py#L121 https://github.com/spacetelescope/jwst/blob/3ea0fa86a40e7038c9d5ca3bcbc071fee82d8cba/jwst/assign_wcs/assign_wcs_step.py#L140 https://github.com/spacetelescope/jwst/blob/3ea0fa86a40e7038c9d5ca3bcbc071fee82d8cba/jwst/extract_1d/extract.py#L809 ... (and others. I can continue, but there are lots, and it's probably better if I just fix them if we decide to go this route.)

braingram commented 3 months ago

Feel free to also push to this branch.

If there are many perhaps it makes sense to keep the log changes outside this PR? They risk breaking the log messages (which this PR does not). Do you think the removal of all newlines from logs is required for this PR?

melanieclarke commented 3 months ago

My concern is that this change does break the log messages - it introduces unexpected formatting. I'd prefer not to remove the multiline functionality without either replacing it or fixing the instances that expect it.

braingram commented 3 months ago

My concern is that this change does break the log messages - it introduces unexpected formatting. I'd prefer not to remove the multiline functionality without either replacing it or fixing the instances that expect it.

Are there any examples of where the splitting by newline is expected (aside from just that splitting is currently what happens)? If so, there are no tests for that behavior (since nothing failed with the removal of MultilineLogger) and I'd say the current state (setting it as the default) introduces more unexpected formatting issues where any logger after jwst is imported now breaks up log messages.

melanieclarke commented 3 months ago

From a software perspective, yes, I agree, the MultiLineLogger is problematic and we should address it. It's definitely better to have our code just log multiple messages than make a secret default that breaks other people's loggers.

From a user perspective, sudden changes in the appearance of the log are disconcerting and distracting. The current log messages were written under a condition where the splitting happens - so if we're removing the splitting, I think we should revise the messages that currently rely on it.

I can help track down as many of these as possible now, and we can fix any remainders in future PRs, but I don't think we should introduce a default change without accounting for it in the code that relies on the current behavior.

melanieclarke commented 3 months ago

@braingram - do you want me to send you changes for the messages affected by the MultiLineLogger here? Or does this need more discussion?

melanieclarke commented 3 months ago

Or, I can send in a separate PR to fix the log messages and we can hold off on this one until that one is in.

braingram commented 3 months ago

Thanks. Sorry for the delay I was tied up in meetings.

I reverted the log changes in this PR and am going to closing it for now. Given the concerns about changing the logging output I don't see any way we can remove MultilineLogger as in many situations it will change the log output.

To highlight a specific example, since MultilineLogger is registered as the default logger within jwst.associations.lib.log_config the log output will depend on the import order. For this log message: https://github.com/spacetelescope/jwst/blob/4ecb40c57aaf1ae99fd6d8d9be66b7530277cf40/jwst/dark_current/dark_current_step.py#L103 the newline is not split because the logger is created before the call to setLoggerClass. However for: https://github.com/spacetelescope/jwst/blob/4ecb40c57aaf1ae99fd6d8d9be66b7530277cf40/jwst/assign_wcs/assign_wcs_step.py#L121 it is split (since the imports in this file trigger importing jwst.associations.lib.log_config). Figuring out which newlines require splitting and which do not to retain the same log output isn't something I can take on at this time.

melanieclarke commented 3 months ago

Okay, thanks for following up @braingram. I'll send in a separate PR to address the messages with newlines and we can tackle the MultiLineLogger after that.