Repository: spacetelescope/jwst

Issue:
Report jwst software version in output log
_Issue [JP-3729](https://jira.stsci.edu/browse/JP-3729) was created on JIRA by [David Law](https://jira.stsci.edu/secure/ViewProfile.jspa?name=dlaw):_

For user support purposes, it would be helpful to report the version of the jwst pipeline software in use in the output log.  For consistency the best location may be the end of the log next to the existing report of the CRDS context used.

I can see arguments for both having this information at the start of the log (print it early before getting into details) and at the end (end of the log stays on screen for longer, while all of the other log info scrolls the start of the log offscreen instantly).  As such let's add to the end rather than changing existing behavior.

Discussion:
codecov[bot]: ## [Codecov](https://app.codecov.io/gh/spacetelescope/jwst/pull/8760?dropdown=coverage&src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=spacetelescope) Report
All modified and coverable lines are covered by tests :white_check_mark:
> Project coverage is 60.77%. Comparing base [(`8381a26`)](https://app.codecov.io/gh/spacetelescope/jwst/commit/8381a261d0b9a51d0ce2e7ac693032c76efac697?dropdown=coverage&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=spacetelescope) to head [(`17d1be2`)](https://app.codecov.io/gh/spacetelescope/jwst/commit/17d1be2e069afd582d2dbf4e36d416cd01a04f6e?dropdown=coverage&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=spacetelescope).
> Report is 3 commits behind head on master.

<details><summary>Additional details and impacted files</summary>


```diff
@@            Coverage Diff             @@
##           master    #8760      +/-   ##
==========================================
+ Coverage   60.63%   60.77%   +0.14%     
==========================================
  Files         372      373       +1     
  Lines       38372    38596     +224     
==========================================
+ Hits        23267    23458     +191     
- Misses      15105    15138      +33     
```

</details>

[:umbrella: View full report in Codecov by Sentry](https://app.codecov.io/gh/spacetelescope/jwst/pull/8760?dropdown=coverage&src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=spacetelescope).   
:loudspeaker: Have feedback on the report? [Share it here](https://about.codecov.io/codecov-pr-comment-feedback/?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=spacetelescope).

braingram: > LG2M in general; I can now see both the CRDS and cal pipeline version in det1, spec2, and spec3 logs.
> 
> The jwst version printed looks unexpected though. Testing this PR I get 1.14.1.dev396+gf252448ee which seems unexpected since development has moved on past 1.15.1
> 
> Indeed, even using a standalone environment with jwst 1.15.1 installed, I till get 1.14.1.dev396+gf252448ee reported by the 1.15.1 environment call to jwst.**version**
> 
> Are there some unresolved issues with the version call?

Thanks for giving this a test. The version was 1.14.1.etc due to the out-of-date tags. I just pushed the updated tags (from the spacetelescope upstream) to my fork. Any local testing will also require pulling new tags to get an updated version (as the version is dynamically set from the git tag).

Patch:
diff --git a/CHANGES.rst b/CHANGES.rst
index 661f78510..eb25ae7a5 100644
--- a/CHANGES.rst
+++ b/CHANGES.rst
@@ -191,6 +191,8 @@ stpipe
   added a `query_step_status()` function to use as an alternative to checking
   `self.skip`. [#8600]
 
+- Log jwst version and crds context at the end of step/pipeline runs. [#8760]
+
 tso_photometry
 --------------
 
diff --git a/jwst/stpipe/core.py b/jwst/stpipe/core.py
index 2a3013919..094b4c1f4 100644
--- a/jwst/stpipe/core.py
+++ b/jwst/stpipe/core.py
@@ -76,19 +76,23 @@ class JwstStep(Step):
         return asn
 
     def finalize_result(self, result, reference_files_used):
+        crds_context = crds_client.get_context_used('jwst')
+
+        if self.parent is None:
+            log.info(f"Results used CRDS context: {crds_context}")
+            log.info(f"Results used jwst version: {__version__}")
+
         if isinstance(result, JwstDataModel):
             result.meta.calibration_software_revision = __version_commit__ or 'RELEASE'
             result.meta.calibration_software_version = __version__
 
+
             if len(reference_files_used) > 0:
                 for ref_name, filename in reference_files_used:
                     if hasattr(result.meta.ref_file, ref_name):
                         getattr(result.meta.ref_file, ref_name).name = filename
                 result.meta.ref_file.crds.sw_version = crds_client.get_svn_version()
-                result.meta.ref_file.crds.context_used = crds_client.get_context_used(result.crds_observatory)
-                if self.parent is None:
-                    log.info(f"Results used CRDS context: {result.meta.ref_file.crds.context_used}")
-
+                result.meta.ref_file.crds.context_used = crds_context
 
     def remove_suffix(self, name):
         return remove_suffix(name)
@@ -98,6 +102,4 @@ class JwstStep(Step):
 # be a subclass of JwstStep so that it will pass checks
 # when constructing a pipeline using JwstStep class methods.
 class JwstPipeline(Pipeline, JwstStep):
-    def finalize_result(self, result, reference_files_used):
-        if isinstance(result, JwstDataModel):
-            log.info(f"Results used CRDS context: {crds_client.get_context_used(result.crds_observatory)}")
+    pass


Test patch:
diff --git a/jwst/stpipe/tests/test_step.py b/jwst/stpipe/tests/test_step.py
index 1c1d3a76d..250fb14d8 100644
--- a/jwst/stpipe/tests/test_step.py
+++ b/jwst/stpipe/tests/test_step.py
@@ -1,3 +1,4 @@
+import logging
 import os
 from os.path import (
     abspath,
@@ -15,8 +16,10 @@ from stpipe.config_parser import ValidationError
 
 from stdatamodels.jwst import datamodels
 
+from jwst import __version__ as jwst_version
 from jwst.white_light import WhiteLightStep
 from jwst.stpipe import Step
+from jwst.tests.helpers import LogWatcher
 
 from jwst.stpipe.tests.steps import (
     EmptyPipeline, MakeListPipeline, MakeListStep,
@@ -39,6 +42,10 @@ WHITELIGHTSTEP_CRDS_MIRI_PARS = {
 
 CRDS_ERROR_STRING = 'PARS-WITHDEFAULTSSTEP: No parameters found'
 
+# used in logging tests below to provide a deterministic crds
+# context to look for in the log messages
+FAKE_CRDS_CONTEXT = "0000.pmap"
+
 
 @pytest.fixture(scope='module')
 def data_path():
@@ -607,3 +614,22 @@ def test_call_with_config(caplog, tmp_cwd):
     ProperPipeline.call(model, config_file=cfg)
 
     assert "newpar1" in caplog.text
+
+
+@pytest.mark.parametrize(
+    "message", [
+        f"Results used CRDS context: {FAKE_CRDS_CONTEXT}",
+        f"Results used jwst version: {jwst_version}",
+    ])
+def test_finalize_logging(monkeypatch, message):
+    """
+    Check that the jwst version and crds context are logged
+    when a step/pipeline is run.
+    """
+    pipeline = EmptyPipeline()
+    model = datamodels.ImageModel()
+    monkeypatch.setattr(crds_client, 'get_context_used', lambda observatory: FAKE_CRDS_CONTEXT)
+    watcher = LogWatcher(message)
+    monkeypatch.setattr(logging.getLogger("jwst.stpipe.core"), "info", watcher)
+    pipeline.run(model)
+    assert watcher.seen