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

Logging error in isrTask

    XMLWordPrintable

Details

    • Bug
    • Status: Done
    • Resolution: Done
    • None
    • ip_isr
    • None
    • 1
    • Data Release Production
    • 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

            tjenness Tim Jenness added a comment -

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

            tjenness Tim Jenness added a comment - Maybe we should change the way we run pytest from sconsUtils so it enables DEBUG logging.

            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.

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

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

            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.

            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.
            tjenness Tim Jenness added a comment -

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

            tjenness Tim Jenness added a comment - mfisherlevine 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. czw 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.

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

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

            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 tjenness's comment).  There are no other debug failures on the package, so I'll merge once Jenkins passes as well.

            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 tjenness 's comment).  There are no other debug failures on the package, so I'll merge once Jenkins passes as well.

            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!

            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

              czw Christopher Waters
              mfisherlevine Merlin Fisher-Levine
              Merlin Fisher-Levine
              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.