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

Port ci_hsc to log package

    XMLWordPrintable

    Details

    • Type: Story
    • Status: Done
    • Resolution: Done
    • Fix Version/s: None
    • Component/s: ci_hsc
    • Labels:
      None

      Description

      Switch from using pex_logging to log in ci_hsc.

        Attachments

          Issue Links

            Activity

            Hide
            swinbank John Swinbank added a comment -

            Frossie Economou requests that we tackle this within the first couple of months of S17.

            Show
            swinbank John Swinbank added a comment - Frossie Economou requests that we tackle this within the first couple of months of S17.
            Hide
            pgee Perry Gee added a comment -

            Jim Bosch I am rather confused about how this is supposed to be done. I altered the python code in ci_hsc to use lsst.log instead of pex_logging, and in some cases that seemed to work OK. In particular, I used lsst.log.Log.getLogger() to replace the pex_logging getDefaultLog, since the two classes both suppor the log.info, debug, warn, and error signatures which seem to be used by a lot of the underlying code.

            However, I see two problems with this approach:

            (1) the log which is created seems to sometimes call code which expects the values -1 or -2 to be acceptable values for the log level. I think these were meaningful to pex_logging, but not to lsst,log.

            (2) I seem to run into code which is called by ci_hsc which expect to be able to call routine in _loggingLib in pex_logging, even though I am not myself including or calling classes in that Library. That seems to indicate that there is code under ci_hsc which depends on pex_logging, even if ci_hsc does not. Am I supposed to chase down anything called by ci_hsc and remove its dependence on pex_logging? Could involve considerably more modules than ci_hsc.

            Show
            pgee Perry Gee added a comment - Jim Bosch I am rather confused about how this is supposed to be done. I altered the python code in ci_hsc to use lsst.log instead of pex_logging, and in some cases that seemed to work OK. In particular, I used lsst.log.Log.getLogger() to replace the pex_logging getDefaultLog, since the two classes both suppor the log.info, debug, warn, and error signatures which seem to be used by a lot of the underlying code. However, I see two problems with this approach: (1) the log which is created seems to sometimes call code which expects the values -1 or -2 to be acceptable values for the log level. I think these were meaningful to pex_logging, but not to lsst,log. (2) I seem to run into code which is called by ci_hsc which expect to be able to call routine in _loggingLib in pex_logging, even though I am not myself including or calling classes in that Library. That seems to indicate that there is code under ci_hsc which depends on pex_logging, even if ci_hsc does not. Am I supposed to chase down anything called by ci_hsc and remove its dependence on pex_logging? Could involve considerably more modules than ci_hsc.
            Hide
            swinbank John Swinbank added a comment -

            Hey Perry Gee — although Jim is always a fount of knowledge, you'll probably find that others, and in particular Hsin-Fang, are able to provide the expertise you need here.

            I don't know the answer to your question 1, but as for 2 I think you should limit yourself to only converting code within ci_hsc itself: other packages will be ported on other tickets.

            Show
            swinbank John Swinbank added a comment - Hey Perry Gee — although Jim is always a fount of knowledge, you'll probably find that others, and in particular Hsin-Fang, are able to provide the expertise you need here. I don't know the answer to your question 1, but as for 2 I think you should limit yourself to only converting code within ci_hsc itself: other packages will be ported on other tickets.
            Hide
            pgee Perry Gee added a comment -

            John Swinbank I don't think I can leave ci_hsc in a state where it doesn't run, so I pretty much have to understand what is going on with (2). What I find is that when I don't setup pex_logging, I eventually get the following message:

            ImportError: Unable to read stored config file processCcd_config (No module named _loggingLib)

            I'm not actually sure what is causing it. I don't see any stored config file which might be causing this.

            Show
            pgee Perry Gee added a comment - John Swinbank I don't think I can leave ci_hsc in a state where it doesn't run, so I pretty much have to understand what is going on with (2). What I find is that when I don't setup pex_logging, I eventually get the following message: ImportError: Unable to read stored config file processCcd_config (No module named _loggingLib) I'm not actually sure what is causing it. I don't see any stored config file which might be causing this.
            Hide
            hchiang2 Hsin-Fang Chiang added a comment -

            (1) Yes. Those calls will need to be ported to use the new log. This page in the Developer Guide may be useful.

            Logging with negative numeric level in pex_logging were for debug messages. But I also saw that -1 was used for warning messages in some old coldes. I'd leave the specific mapping to your judgement.

            (2) Yes. It's possible that dependent packages need to remove pex_logging use before ci_hsc can remove pex_logging. In other words, this ticket may be blocked by DM-8357 and other packages.

            Show
            hchiang2 Hsin-Fang Chiang added a comment - (1) Yes. Those calls will need to be ported to use the new log . This page in the Developer Guide may be useful. Logging with negative numeric level in pex_logging were for debug messages. But I also saw that -1 was used for warning messages in some old coldes. I'd leave the specific mapping to your judgement. (2) Yes. It's possible that dependent packages need to remove pex_logging use before ci_hsc can remove pex_logging. In other words, this ticket may be blocked by DM-8357 and other packages.
            Hide
            pgee Perry Gee added a comment -

            Hsin-Fang Chiang Looking over meas_modelfit, the usage seems to be to set a log level from 1 to 10, which gets translated into -1 to -10. The debug log can then be filtered for importance. Is this functionality completely missing from lsst.log, or can it be resurrected somehow?

            Show
            pgee Perry Gee added a comment - Hsin-Fang Chiang Looking over meas_modelfit, the usage seems to be to set a log level from 1 to 10, which gets translated into -1 to -10. The debug log can then be filtered for importance. Is this functionality completely missing from lsst.log, or can it be resurrected somehow?
            Hide
            pgee Perry Gee added a comment -

            @jbosch, do you care about this debugLog functionality for meas_ modelfit, or can I turn them all to log.debug's?

            Show
            pgee Perry Gee added a comment - @jbosch, do you care about this debugLog functionality for meas_ modelfit, or can I turn them all to log.debug's?
            Hide
            hchiang2 Hsin-Fang Chiang added a comment -

            Perry Gee please see the Logging page in the Developer Guide, section "Fine-level Verbosity in Tracing".

            How many levels are actually used? How many do you want? There are examples in afw and ip_diffim if you decide to go for fine-level tracing.

            Show
            hchiang2 Hsin-Fang Chiang added a comment - Perry Gee please see the Logging page in the Developer Guide, section "Fine-level Verbosity in Tracing". How many levels are actually used? How many do you want? There are examples in afw and ip_diffim if you decide to go for fine-level tracing.
            Hide
            pgee Perry Gee added a comment -

            OK, thanks for the information. I can replicate what is in meas_modelfit with the Fine-level capability.

            Show
            pgee Perry Gee added a comment - OK, thanks for the information. I can replicate what is in meas_modelfit with the Fine-level capability.
            Hide
            pgee Perry Gee added a comment -

            Hsin-Fang Chiang

            After examining the code, it appears to me that I can replace the log.debug<n> templates with traceLogging. However, it will create the following difference in behavior:

            Since values which are used in the pex_logging log.debug<n> code all translate into log levels between -1 and -10, some could be enabled even if the whole range of values from -1 to -10 are not enabled. But the new lsst.log fine resolution Trace<n> capabilities all require that the level be set to TRACE. The difference is that all messages of level DEBUG and larger will also be enabled.

            I'm not sure if this is a problem, because I am not sure how the debug<n> construct in pex_logging was used previously,

            Show
            pgee Perry Gee added a comment - Hsin-Fang Chiang After examining the code, it appears to me that I can replace the log.debug<n> templates with traceLogging. However, it will create the following difference in behavior: Since values which are used in the pex_logging log.debug<n> code all translate into log levels between -1 and -10, some could be enabled even if the whole range of values from -1 to -10 are not enabled. But the new lsst.log fine resolution Trace<n> capabilities all require that the level be set to TRACE. The difference is that all messages of level DEBUG and larger will also be enabled. I'm not sure if this is a problem, because I am not sure how the debug<n> construct in pex_logging was used previously,
            Hide
            hchiang2 Hsin-Fang Chiang added a comment -

            If you decide to go for the scheme as in https://developer.lsst.io/coding/logging.html "Fine-level Verbosity in Tracing", to avoid confusion please only log in the DEBUG level (not TRACE) using logger names such as "TRACE2.meas.algorithms.starSelector". There are some more examples in ip_diffim and afw.

            You can enable a single TRACEn via its specific logger name (e.g. {{lsst.log.Log.getLogger("TRACE2.meas.algorithms.starSelector").setLevel(lsst.log.DEBUG) }}), although I'm not sure if that is practically useful. It's probably more useful to set a threshold using {{lsst.log.utils.traceSetAt() }}. If more syntactic sugar is desired please file new tickets.

            Sometimes it may not be necessary to convert codes to this scheme described above/in the Dev Guide. For example, in meas_modelfit/src/TruncatedGaussian.cc pex::logging::Debug debug<8> is used, but only numeric level 8 is used. In meas_modelfit/src/SoftenedLinearPrior.cc debug<7> is used and only 7 is used. Because only one fine level is used in one logger, I see no reasons to use the more complicated scheme; why not convert them all to DEBUG level, they can be controlled separately through the different logger names anyway. With that said, I don't understand these science codes well enough, so it's up to you whether it is important to keep the number 8 or 7.

            It's understood that the behavior of the new system is not exactly the same as the old pex_logging. If you are interested in how we reached here, you may want to read RFC-203.

            Show
            hchiang2 Hsin-Fang Chiang added a comment - If you decide to go for the scheme as in https://developer.lsst.io/coding/logging.html "Fine-level Verbosity in Tracing", to avoid confusion please only log in the DEBUG level ( not TRACE ) using logger names such as "TRACE2.meas.algorithms.starSelector". There are some more examples in ip_diffim and afw . You can enable a single TRACEn via its specific logger name (e.g. {{lsst.log.Log.getLogger("TRACE2.meas.algorithms.starSelector").setLevel(lsst.log.DEBUG) }}), although I'm not sure if that is practically useful. It's probably more useful to set a threshold using {{lsst.log.utils.traceSetAt() }}. If more syntactic sugar is desired please file new tickets. Sometimes it may not be necessary to convert codes to this scheme described above/in the Dev Guide. For example, in meas_modelfit/src/TruncatedGaussian.cc pex::logging::Debug debug<8> is used, but only numeric level 8 is used. In meas_modelfit/src/SoftenedLinearPrior.cc debug<7> is used and only 7 is used. Because only one fine level is used in one logger, I see no reasons to use the more complicated scheme; why not convert them all to DEBUG level, they can be controlled separately through the different logger names anyway. With that said, I don't understand these science codes well enough, so it's up to you whether it is important to keep the number 8 or 7. It's understood that the behavior of the new system is not exactly the same as the old pex_logging. If you are interested in how we reached here, you may want to read RFC-203 .
            Hide
            hchiang2 Hsin-Fang Chiang added a comment -

            I did a quick search in meas_modelfit and found 5 c++ files that use pex::logging::Debug:

            • src/TruncatedGaussian.cc
              Only debug level <8> is used in a logger named "meas.modelfit.TruncatedGaussian"
            • src/AdaptiveImportanceSampler.cc
              Debug level <7> and <8> are used in a logger named "meas.modelfit.AdaptiveImportanceSample". Only <8> in computeRobustWeights; only <7> in AdaptiveImportanceSampler::run.
            • src/optimizer.cc
              Debug level <7> and <10> are used.
            • src/integrals.cc
              Only debug level <8> is used in a logger named "meas.modelfit.integrals"
            • src/SoftenedLinearPrior.cc
              Only debug level <7> is used in a logger named "meas.modelfit.SoftenedLinearPrior"
            Show
            hchiang2 Hsin-Fang Chiang added a comment - I did a quick search in meas_modelfit and found 5 c++ files that use pex::logging::Debug : src/TruncatedGaussian.cc Only debug level <8> is used in a logger named "meas.modelfit.TruncatedGaussian" src/AdaptiveImportanceSampler.cc Debug level <7> and <8> are used in a logger named "meas.modelfit.AdaptiveImportanceSample". Only <8> in computeRobustWeights; only <7> in AdaptiveImportanceSampler::run. src/optimizer.cc Debug level <7> and <10> are used. src/integrals.cc Only debug level <8> is used in a logger named "meas.modelfit.integrals" src/SoftenedLinearPrior.cc Only debug level <7> is used in a logger named "meas.modelfit.SoftenedLinearPrior"
            Hide
            pgee Perry Gee added a comment -

            I'm not exactly sure how they are used, either. I was planning to give this the Jim to review, since I suppose that the primary usage is during debugging.

            I've already done the conversion of this code to use TraceLogging, though I am not exactly sure if it was necessary. So I will probably just leave it as I've change it, and see how the review goes.

            Thanks.
            Perry

            Show
            pgee Perry Gee added a comment - I'm not exactly sure how they are used, either. I was planning to give this the Jim to review, since I suppose that the primary usage is during debugging. I've already done the conversion of this code to use TraceLogging, though I am not exactly sure if it was necessary. So I will probably just leave it as I've change it, and see how the review goes. Thanks. Perry
            Hide
            pgee Perry Gee added a comment -

            I substituted the lsst.log.Log.getDefaultLogger() for the lsst.pex.logging.getDefaultLog(). That appeared to be the only change required.

            The two loggers are not identical in behavio r(some of the methods, such as log.debug differ). But by default they log only to the screen and are unnamed.

            I do not see any calls in this package which differ between the two packages.

            Changes are in tickets/DM-8356

            Show
            pgee Perry Gee added a comment - I substituted the lsst.log.Log.getDefaultLogger() for the lsst.pex.logging.getDefaultLog(). That appeared to be the only change required. The two loggers are not identical in behavio r(some of the methods, such as log.debug differ). But by default they log only to the screen and are unnamed. I do not see any calls in this package which differ between the two packages. Changes are in tickets/ DM-8356
            Hide
            pgee Perry Gee added a comment -

            This should be a 10 minute review

            Show
            pgee Perry Gee added a comment - This should be a 10 minute review
            Hide
            swinbank John Swinbank added a comment -

            Going to steal this review for myself, since I'd like to learn about the new logger. Sorry Merlin Fisher-Levine!

            Show
            swinbank John Swinbank added a comment - Going to steal this review for myself, since I'd like to learn about the new logger. Sorry Merlin Fisher-Levine !
            Hide
            swinbank John Swinbank added a comment -

            I'm confused by all the discussion above about meas_modelfit, while the only changes on the ticket branch seem to be in ci_hsc. Perry Gee, can you clarify what's happening here, please?

            Show
            swinbank John Swinbank added a comment - I'm confused by all the discussion above about meas_modelfit, while the only changes on the ticket branch seem to be in ci_hsc. Perry Gee , can you clarify what's happening here, please?
            Hide
            swinbank John Swinbank added a comment -

            Huh, looks like the _modelfit changes landed in DM-8357, but were discussed here. How confusing!

            Show
            swinbank John Swinbank added a comment - Huh, looks like the _modelfit changes landed in DM-8357 , but were discussed here. How confusing!
            Hide
            pgee Perry Gee added a comment -

            I think that the thread was natural enough. The discussion started up on this thread because running ci_hsc with lsst.log caused downstream failures in meas_modelfit. This conversation is referred to in 8357.

            Show
            pgee Perry Gee added a comment - I think that the thread was natural enough. The discussion started up on this thread because running ci_hsc with lsst.log caused downstream failures in meas_modelfit. This conversation is referred to in 8357.
            Hide
            swinbank John Swinbank added a comment -

            Hey Hsin-Fang Chiang

            I understood from the discussion above that it was necessary that all the dependencies of ci_hsc be converted to use pex_logging before it was possible to convert ci_hsc itself. However, I just tried running the tickets/DM-8356 branch of ci_hsc with the latest weekly (w51) of meas_modelfit which pre-dates the logging conversion, and it worked fine!

            Can you explain a bit what's going on here? Do dependencies need to be converted or not? How do the logging systems interact?

            Thanks!

            Show
            swinbank John Swinbank added a comment - Hey Hsin-Fang Chiang — I understood from the discussion above that it was necessary that all the dependencies of ci_hsc be converted to use pex_logging before it was possible to convert ci_hsc itself. However, I just tried running the tickets/ DM-8356 branch of ci_hsc with the latest weekly (w51) of meas_modelfit which pre-dates the logging conversion, and it worked fine! Can you explain a bit what's going on here? Do dependencies need to be converted or not? How do the logging systems interact? Thanks!
            Hide
            hchiang2 Hsin-Fang Chiang added a comment -

            I said it's possible (not necessary!) that dependent packages need to remove pex_logging first. From my experience, the dependency blocking sometimes happened in c++ codes; mostly it was afw and somehow I couldn't remove downstream pex_logging dependency in c++ while afw still used pex_logging. I suspected it was some SWIG thing but didn't follow through to know exactly why. If you are really curious I may go back to find an example.

            On second thought, it's indeed puzzling how meas_modelfit could block ci_hsc. There seems no log passing, and after all, ci_hsc is pure python, right? I didn't try anything practical here. Maybe Perry Gee can say more what he saw?

            Show
            hchiang2 Hsin-Fang Chiang added a comment - I said it's possible (not necessary !) that dependent packages need to remove pex_logging first. From my experience, the dependency blocking sometimes happened in c++ codes; mostly it was afw and somehow I couldn't remove downstream pex_logging dependency in c++ while afw still used pex_logging. I suspected it was some SWIG thing but didn't follow through to know exactly why. If you are really curious I may go back to find an example. On second thought, it's indeed puzzling how meas_modelfit could block ci_hsc. There seems no log passing, and after all, ci_hsc is pure python, right? I didn't try anything practical here. Maybe Perry Gee can say more what he saw?
            Hide
            pgee Perry Gee added a comment -

            No, it's not pure python. It runs the pipeline, which calls C++ for most of its measurement algorithms. The problem was occurring in swig I believe, though it has been weeks, and I don't really recall. I never tracked down the smoking gun, nor did I feel motivated to do so when the problem when away. But I will try to reproduce it when I have the time. I may not have been in the build and setup state I thought I was.

            Show
            pgee Perry Gee added a comment - No, it's not pure python. It runs the pipeline, which calls C++ for most of its measurement algorithms. The problem was occurring in swig I believe, though it has been weeks, and I don't really recall. I never tracked down the smoking gun, nor did I feel motivated to do so when the problem when away. But I will try to reproduce it when I have the time. I may not have been in the build and setup state I thought I was.
            Hide
            swinbank John Swinbank added a comment -

            Change looks basically fine. Trivial comment on the PR.

            As a reminder, our procedure is that the author of the code makes the PR before they submit it for review. See e.g. here.

            Show
            swinbank John Swinbank added a comment - Change looks basically fine. Trivial comment on the PR . As a reminder, our procedure is that the author of the code makes the PR before they submit it for review. See e.g. here .
            Hide
            swinbank John Swinbank added a comment -

            Thanks both. I suspect that the problem Perry saw was just a coincidence, and wasn't actually related to the logging transition at all. Not worth spending more timing tracking it down.

            Show
            swinbank John Swinbank added a comment - Thanks both. I suspect that the problem Perry saw was just a coincidence, and wasn't actually related to the logging transition at all. Not worth spending more timing tracking it down.

              People

              Assignee:
              pgee Perry Gee
              Reporter:
              hchiang2 Hsin-Fang Chiang
              Reviewers:
              John Swinbank
              Watchers:
              Hsin-Fang Chiang, John Swinbank, Lauren MacArthur, Merlin Fisher-Levine, Perry Gee
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  CI Builds

                  No builds found.