JP-4129: Work around default CRDS log configuration to allow stpipe capture

[melanieclarke]

Toward JP-4129

Workaround for CRDS logging configuration, to allow stpipe to capture log messages from the "CRDS" logger.

The default console logger assigned by CRDS is removed when stpipe configures loggers, then is restored when the configuration is undone.

Tasks

• update or add relevant tests
• update relevant docstrings and / or docs/ page
• Does this PR change any API used downstream? (if not, label with no-changelog-entry-needed)
  • write news fragment(s) in changes/: echo "changed something" > changes/<PR#>.<changetype>.rst (see changelog readme for instructions)
  • run regression tests with this branch installed (stpipe@git+https://github.com/<fork>/stpipe.git@<branch>)
    • jwst regression test
    • romancal regression test

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 95.71%. Comparing base (a75274a) to head (6517a37).
⚠️ Report is 4 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #312      +/-   ##
==========================================
+ Coverage   95.66%   95.71%   +0.05%     
==========================================
  Files          35       35              
  Lines        3391     3433      +42     
==========================================
+ Hits         3244     3286      +42     
  Misses        147      147              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[melanieclarke]

@braingram @pllim - I remembered why we couldn't directly capture the CRDS logger in the initial logging refactoring. It's because CRDS configures a logger on import, including adding a non-optional stream handler. If stpipe attaches its own handlers without removing the existing stream handler, users will see duplicate log messages with slightly different formats.

It occurs to me looking at it now, though, that since we have special handling for "py.warnings", there's no reason we couldn't also have special handling for the CRDS logger. The stpipe and crds packages already have a special relationship, so we don't need to treat it like any other anonymous dependency.

This PR is a proposal that uses the CRDS log interface to remove its own stream handler when logging is configured (via stpipe call or command line) and restore it when the logging configuration is undone. With this change, and adding "CRDS" to the stpipe loggers for jwst, I see CRDS logging messages captured in the datamodel logs and no duplicate messages in the terminal. If I run a call process from Python with configure_log=False, I no longer see the unwanted CRDS log messages that appeared before.

If we like this proposal I can add some tests for it.

Edit: to clarify, this does not fix the timing problem for JP-4129, where the initial messages from pipeline start up are missed in the datamodel logs, it just fixes the separate log capture and configuration problem for the CRDS logger specifically.

[pllim]

I like the idea in principle! I will let stpipe maintainers do the actual code review. Thanks!

[braingram]

Thanks! Looks great. How would you like to coordinate this update with the other logging work? I doubt the code changes will overlap but the tests might (and this might be easier to test in combination with the other logging changes).

[pllim]

I can wait for this one to go in first.

[melanieclarke]

Sounds good, I'll clean it up and add some tests.

The initial CRDS messages aren't the only ones issued while running most steps, so I think it should still be easy enough to test this without the other log changes.

[melanieclarke]

Regtests with jwst and romancal on main:
https://github.com/spacetelescope/RegressionTests/actions/runs/25505396238
https://github.com/spacetelescope/RegressionTests/actions/runs/25505502739

Tests with CRDS added to the stpipe loggers for jwst (spacetelescope/jwst#10523):
https://github.com/spacetelescope/RegressionTests/actions/runs/25506932686

All passing.

[melanieclarke]

To test locally on one of the regression test exposures, along with jwst PR spacetelescope/jwst#10523:
strun assign_wcs jw01538046001_03105_00002_nrcalong_rate.fits
CRDS message "DEV calibration SW identified. Defaulting to Edit Context." should appear only once.

Then, there should be a CRDS message in the cal logs for the output model:

from stdatamodels.jwst import datamodels
model = datamodels.open("jw01538046001_03105_00002_nrcalong_assignwcsstep.fits")
print("CRDS - INFO -  DEV calibration SW identified. Defaulting to Edit Context." in "\n".join(model.cal_logs.assign_wcs))

prints True.

[braingram]

Thanks for putting this together. I left a few suggestions about underscoring the new crds_client functions (since I'm assuming we don't want this to be misinterpreted as public api).

I'd also be ok with in-lining the calls to crds.core.log (since the new functions only have 1 line of code).

Can (and should) we check if the crds console handler is already detached/attached so the stpipe logging configuration doesn't apply or remove something the user configured?

[melanieclarke]

I left a few suggestions about underscoring the new crds_client functions (since I'm assuming we don't want this to be misinterpreted as public api).

Will do.

I'd also be ok with in-lining the calls to crds.core.log (since the new functions only have 1 line of code).

I put them in the crds_client module because there are warnings there about not importing crds directly anywhere but in that module.

Can (and should) we check if the crds console handler is already detached/attached so the stpipe logging configuration doesn't apply or remove something the user configured?

The remove function won't do anything if there's no handler attached currently, so that should be okay as is. I was on the fence about checking whether there was previously a console logger before adding it back in the undo. I can look into it now.

[braingram]

I put them in the crds_client module because there are warnings there about not importing crds directly anywhere but in that module.

Thanks for pointing that out. It looks like it was introduced in:
spacetelescope/jwst#4113
maybe we should remove that comment since it's no longer accurate.

[melanieclarke]

Okay, I removed the functions from crds_client and called the CRDS log interface directly from stpipe.log instead. Also now checking for a previous console before adding one in for undo.

[braingram]

Testing locally works a treat!

Thanks for making this improvement.