Uploaded image for project: 'Data Management'
  1. Data Management
  2. DM-38044

Logging error in isrTask

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Done
    • Resolution: Done
    • Fix Version/s: None
    • Component/s: ip_isr
    • Labels:
      None
    • Story Points:
      1
    • Epic Link:
    • Team:
      Data Release Production
    • Urgent?:
      Yes

      Description

      The lines reading

                              self.log.debug("  Overscan stats for amplifer %s: %f +/- %f",                                       amp.getName(), overscanResults.overscanMean,                                       overscanResults.overscanSigma)

      and

                              self.log.debug("  Overscan stats for amplifer %s after correction: %f +/- %f",                                       amp.getName(), overscanResults.residualMean,                                       overscanResults.residualSigma)

      result in a logging error when the lines are active.

       

      To reproduce just change them to info level and run (or use the magic that I can never remember to set the task to debug level logging)

      pipetask run -b /repo/embargo -i LATISS/raw/all,refcats,LATISS/calib -o u/<yourusername>/scratch -d "exposure.day_obs=20230215 AND exposure.seq_num=233 AND instrument='LATISS'" -p $DRP_PIPE_DIR/pipelines/LATISS/DRP.yaml#isr -c isr:doFlat=False

        Attachments

          Issue Links

            Activity

            Hide
            tjenness Tim Jenness added a comment -

            Maybe we should change the way we run pytest from sconsUtils so it enables DEBUG logging.

            Show
            tjenness Tim Jenness added a comment - Maybe we should change the way we run pytest from sconsUtils so it enables DEBUG logging.
            Hide
            mfisherlevine Merlin Fisher-Levine added a comment -

            I reviewed and the fix looks good. And I independently said the same thing as I've just seen Tim has on the PR, though I guess I was asking about ISR, and Tim is asking about all of our tests in general, which would be much better actually! Obviously if that gets ticketed/done then ignore my comment on the PR.

            Show
            mfisherlevine Merlin Fisher-Levine added a comment - I reviewed and the fix looks good. And I independently said the same thing as I've just seen Tim has on the PR, though I guess I was asking about ISR, and Tim is asking about all of our tests in general, which would be much better actually! Obviously if that gets ticketed/done then ignore my comment on the PR.
            Hide
            tjenness Tim Jenness added a comment -

            I've had a quick look at the logging and learned that:

            0. The "Value Failure" debug log message in calibType.py is not very useful unless the thing being logged has a string representation.
            1. It's probably a good idea to turn it on.
            2. You do get a runtime failure in the test if you have mistyped or miscounted the variables in the log message.
            3. Log output does not get sent to stdout if we use xdist (which we do). There is an option to send log output to a file for later inspection but we'd need to modify jenkins to make that file available. It's annoying that log output does not get embedded in the JUnit XML file which we are already harvesting.
            4. The output of logging in tests is very informative.
            5. I have no idea what the test failure was in this ticket because the tests do all pass even with DEBUG enabled and there is code coverage of the lines in question. Merlin Fisher-Levine do you have a copy of the actual error that this is fixing?

            I will file a ticket for doing at least the minimum of internally setting log level to DEBUG

            Show
            tjenness Tim Jenness added a comment - I've had a quick look at the logging and learned that: 0. The "Value Failure" debug log message in calibType.py is not very useful unless the thing being logged has a string representation. 1. It's probably a good idea to turn it on. 2. You do get a runtime failure in the test if you have mistyped or miscounted the variables in the log message. 3. Log output does not get sent to stdout if we use xdist (which we do). There is an option to send log output to a file for later inspection but we'd need to modify jenkins to make that file available. It's annoying that log output does not get embedded in the JUnit XML file which we are already harvesting. 4. The output of logging in tests is very informative. 5. I have no idea what the test failure was in this ticket because the tests do all pass even with DEBUG enabled and there is code coverage of the lines in question. Merlin Fisher-Levine do you have a copy of the actual error that this is fixing? I will file a ticket for doing at least the minimum of internally setting log level to DEBUG
            Hide
            mfisherlevine Merlin Fisher-Levine added a comment -

            I think you just have to enable parallel overscan to have that fire, so if there's a place where we're using a config, you want isrConfig.overscan.doParallelOverscan = True and that should hit that block in the bad way.

            Show
            mfisherlevine Merlin Fisher-Levine added a comment - I think you just have to enable parallel overscan to have that fire, so if there's a place where we're using a config, you want isrConfig.overscan.doParallelOverscan = True and that should hit that block in the bad way.
            Hide
            tjenness Tim Jenness added a comment -

            Merlin Fisher-Levine I do get code coverage on the lines that are fixed on this ticket. If that overscan switch causes some problem that leads to bad values that leads to a broken log message then it would be great if that switch could be turned on in a test. Christopher Waters before I turn on debug locally, you can run pytest --log-level=DEBUG --log-cli-level=DEBUG tests to make it enable debug messages to show that you get a bad log message without this fix.

            Show
            tjenness Tim Jenness added a comment - Merlin Fisher-Levine I do get code coverage on the lines that are fixed on this ticket. If that overscan switch causes some problem that leads to bad values that leads to a broken log message then it would be great if that switch could be turned on in a test. Christopher Waters before I turn on debug locally, you can run pytest --log-level=DEBUG --log-cli-level=DEBUG tests to make it enable debug messages to show that you get a bad log message without this fix.
            Hide
            mfisherlevine Merlin Fisher-Levine added a comment -

            Not to just pass the buck, but that's something Chris is better positioned to do wrt isr task testing, plus it also belong on this ticket, so Christopher Waters could you also add that config option to one of the isr tests please? Kinda surprised it's not already being run somewhere already though, but perhaps the test is too unit-y to hit that or something...

            Show
            mfisherlevine Merlin Fisher-Levine added a comment - Not to just pass the buck, but that's something Chris is better positioned to do wrt isr task testing, plus it also belong on this ticket, so Christopher Waters could you also add that config option to one of the isr tests please? Kinda surprised it's not already being run somewhere already though, but perhaps the test is too unit-y to hit that or something...
            Hide
            czw Christopher Waters added a comment -

            It took a bit longer than I expected to converge, but I have updated the tests/test_isrTask.py to use parallel overscan by default, only disabling for one test which finds different masks with that enabled (parallel overscan fixes the problem on that mock image).  This test now fails on main and succeeds on the ticket branch (only with the debug apparatus from Tim Jenness's comment).  There are no other debug failures on the package, so I'll merge once Jenkins passes as well.

            Show
            czw Christopher Waters added a comment - It took a bit longer than I expected to converge, but I have updated the tests/test_isrTask.py to use parallel overscan by default, only disabling for one test which finds different masks with that enabled (parallel overscan fixes the problem on that mock image).  This test now fails on main and succeeds on the ticket branch (only with the debug apparatus from Tim Jenness 's comment).  There are no other debug failures on the package, so I'll merge once Jenkins passes as well.
            Hide
            mfisherlevine Merlin Fisher-Levine added a comment -

            That sounds wonderful, thanks for that, and sorry it took a little longer to converge than expected. I think that this plus Tim's ticket will be a big win overall though!

            Show
            mfisherlevine Merlin Fisher-Levine added a comment - That sounds wonderful, thanks for that, and sorry it took a little longer to converge than expected. I think that this plus Tim's ticket will be a big win overall though!

              People

              Assignee:
              czw Christopher Waters
              Reporter:
              mfisherlevine Merlin Fisher-Levine
              Reviewers:
              Merlin Fisher-Levine
              Watchers:
              Christopher Waters, Merlin Fisher-Levine, Patrick Ingraham, Tim Jenness
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Jenkins

                  No builds found.