Uploaded image for project: 'Request For Comments'
  1. Request For Comments
  2. RFC-245

Add VERBOSE log level (was: Change the default log level from INFO to WARN)

    XMLWordPrintable

    Details

    • Type: RFC
    • Status: Implemented
    • Resolution: Done
    • Component/s: DM
    • Labels:
      None

      Description

      The current default log level is INFO, but I propose that we change it to WARN.

      I.e.

      • WARN Usual level, anything that is printed is interesting every time you see it
      • INFO Extra verbosity if you are feeling nosy or something's odd (i.e. the first layer of added verbosity)
      • DEBUG The sort of thing that you only need if you're willing to wade through a lot of semi-random information
      • TRACE Even more material, but now specific to different sub-systems.

      If you consult https://docs.python.org/2/howto/logging.html, "When to use logging” section you'll note that "The default level is WARNING" and INFO means, "Confirmation that things are working as expected".

        Attachments

          Issue Links

            Activity

            No builds found.
            rhl Robert Lupton created issue -
            Hide
            Parejkoj John Parejko added a comment -

            I like this proposal. Logging should not mask useful warnings with other things, unless requested to be more verbose. We'll probably want to use INFO for production runs, but we can configure that when it's needed.

            Show
            Parejkoj John Parejko added a comment - I like this proposal. Logging should not mask useful warnings with other things, unless requested to be more verbose. We'll probably want to use INFO for production runs, but we can configure that when it's needed.
            Hide
            hchiang2 Hsin-Fang Chiang added a comment -

            Currently our Developer Guide says

            FATAL: for severe errors that may prevent further execution of the component.
            ERROR: for errors that may still allow the execution to continue.
            WARN: for conditions that may indicate a problem but that allow continued execution.
            INFO: for information that is of interest during normal execution including production.
            DEBUG: for information that is of interest to developers but not of interest during production.
            TRACE: for detailed information when debugging.

            They were added after RFC-203. I don't think they are inconsistent with this RFC either way, but depending on how this goes we may want to update the Developer Guide as well.

            Show
            hchiang2 Hsin-Fang Chiang added a comment - Currently our Developer Guide says FATAL: for severe errors that may prevent further execution of the component. ERROR: for errors that may still allow the execution to continue. WARN: for conditions that may indicate a problem but that allow continued execution. INFO: for information that is of interest during normal execution including production. DEBUG: for information that is of interest to developers but not of interest during production. TRACE: for detailed information when debugging. They were added after RFC-203 . I don't think they are inconsistent with this RFC either way, but depending on how this goes we may want to update the Developer Guide as well.
            Hide
            rowen Russell Owen added a comment - - edited

            I am against this proposal. As Hsin-Fang Chiang says: INFO: for information that is of interest during normal execution including production. To me this is a clear indication that INFO messages normally should be shown.

            I think there are at least 4 different use cases, each of which may want slightly different defaults:

            • Experimentation, e.g. in a python interpreter or Jupyter notebook. Info is liable to be of great interest in this situation since feedback is useful while experimenting. It is a pain to set the debug level in this situation, so I suggest erring on the side of caution and using INFO. However, in the interest of reducing verbosity I suggest omitting data IDs and date from each message (which is, I believe the planned default as of 11/19).
            • Running tasks from the command line. In this situation the right level depends on whether this is routine work (in which case INFO might be excessive) or not (in which case INFO is fine and DEBUG might be wanted). Note that debug levels are trivial to set from the command line, so the default is not as important in this situation. Note that the date and data ID are probably useful (especially when using -j > 1) even though it adds verbosity.
            • Running unit tests. This is a mix of the above two cases and all output goes to a log file. If something goes wrong then INFO is clearly more useful than WARN, but it's probably not worth special configuration for automatic test execution. Normally tests pass, and if one fails, the user can then decide what logging is appropriate to debug the problem.
            • Production runs. INFO seems likely to be appropriate, but in this situation it is perfectly reasonable to fine tune levels and output format as required, so the default is not very important.
            Show
            rowen Russell Owen added a comment - - edited I am against this proposal. As Hsin-Fang Chiang says: INFO: for information that is of interest during normal execution including production. To me this is a clear indication that INFO messages normally should be shown. I think there are at least 4 different use cases, each of which may want slightly different defaults: Experimentation, e.g. in a python interpreter or Jupyter notebook. Info is liable to be of great interest in this situation since feedback is useful while experimenting. It is a pain to set the debug level in this situation, so I suggest erring on the side of caution and using INFO. However, in the interest of reducing verbosity I suggest omitting data IDs and date from each message (which is, I believe the planned default as of 11/19). Running tasks from the command line. In this situation the right level depends on whether this is routine work (in which case INFO might be excessive) or not (in which case INFO is fine and DEBUG might be wanted). Note that debug levels are trivial to set from the command line, so the default is not as important in this situation. Note that the date and data ID are probably useful (especially when using -j > 1) even though it adds verbosity. Running unit tests. This is a mix of the above two cases and all output goes to a log file. If something goes wrong then INFO is clearly more useful than WARN, but it's probably not worth special configuration for automatic test execution. Normally tests pass, and if one fails, the user can then decide what logging is appropriate to debug the problem. Production runs. INFO seems likely to be appropriate, but in this situation it is perfectly reasonable to fine tune levels and output format as required, so the default is not very important.
            Hide
            ctslater Colin Slater added a comment -

            I would rather have INFO. There are lots of statistics that are printed out that can be useful for diagnosing bad behaviors that don't rise to the level of a warning, and I'd rather print too much and have that immediately available instead of having to rerun a failed image to get the diagnostics.

            Show
            ctslater Colin Slater added a comment - I would rather have INFO. There are lots of statistics that are printed out that can be useful for diagnosing bad behaviors that don't rise to the level of a warning, and I'd rather print too much and have that immediately available instead of having to rerun a failed image to get the diagnostics.
            Hide
            tjenness Tim Jenness added a comment -

            Re-reading this RFC I am somewhat surprised that there is nothing between INFO and DEBUG. For Starlink applications INFO was the default and DEBUG was for lots and lots of detail that you would only ever turn on if you wanted to be swamped because you were trying to sort out a problem. We had a VERBOSE option for information that was useful some of the time (for example, showing how an algorithm was converging) and for production runs I always enabled VERBOSE logging. It was definitely true that the default command line output of tasks was INFO and that people got annoyed if running a task generated pages and pages of output by default.

            I worry that moving the default to WARN means the the log files will be mostly empty without any feedback at all and general users will then want to re-run with INFO enabled (and be potentially swamped), but keeping it at INFO means we'll add more and more output there that might be useful for production but won't necessarily be useful for the general user.

            I also understand that adding a whole new log level may just be moving the goal posts.

            Show
            tjenness Tim Jenness added a comment - Re-reading this RFC I am somewhat surprised that there is nothing between INFO and DEBUG. For Starlink applications INFO was the default and DEBUG was for lots and lots of detail that you would only ever turn on if you wanted to be swamped because you were trying to sort out a problem. We had a VERBOSE option for information that was useful some of the time (for example, showing how an algorithm was converging) and for production runs I always enabled VERBOSE logging. It was definitely true that the default command line output of tasks was INFO and that people got annoyed if running a task generated pages and pages of output by default. I worry that moving the default to WARN means the the log files will be mostly empty without any feedback at all and general users will then want to re-run with INFO enabled (and be potentially swamped), but keeping it at INFO means we'll add more and more output there that might be useful for production but won't necessarily be useful for the general user. I also understand that adding a whole new log level may just be moving the goal posts.
            Hide
            jgates John Gates added a comment -

            I think WARN should only be used when something at least somewhat bad happens. The usual problem I have had with log files is locating relevant information in enormous log files. If everything is WARN level, it's very difficult to zero in on unusual inputs which are often the most useful when a problem happens.

            Show
            jgates John Gates added a comment - I think WARN should only be used when something at least somewhat bad happens. The usual problem I have had with log files is locating relevant information in enormous log files. If everything is WARN level, it's very difficult to zero in on unusual inputs which are often the most useful when a problem happens.
            Hide
            rhl Robert Lupton added a comment -

            I stand by this proposal; when things go well we don't need the chatter that INFO produces and it makes it harder to see warnings. I'm not sure what Colin Slater's use case is – if you're expecting problems, by all means run at INFO (and we might want to do that in production where we are filtering the logs anyway).

            Re Tim's comments: I agree. That was why I had multiple easy-to-use TRACE levels (we could have called them DEBUG); but that's all long ago. I think the Hsin-Fang Chiang said that it was hard to add more levels to the logging without custom code.

            Show
            rhl Robert Lupton added a comment - I stand by this proposal; when things go well we don't need the chatter that INFO produces and it makes it harder to see warnings. I'm not sure what Colin Slater 's use case is – if you're expecting problems, by all means run at INFO (and we might want to do that in production where we are filtering the logs anyway). Re Tim's comments: I agree. That was why I had multiple easy-to-use TRACE levels (we could have called them DEBUG); but that's all long ago. I think the Hsin-Fang Chiang said that it was hard to add more levels to the logging without custom code.
            Hide
            tjenness Tim Jenness added a comment -

            I'm not entirely sold on the idea of the default situation being that no messages turn up other than warnings. To me, warnings indicate problems that we should try to solve rather than stuff that can usually be ignored. It seems like INFO is too verbose but if it's not possible to add an extra level between INFO and DEBUG then I'm at a bit of a loss how to proceed (the description for TRACE above sounds far too verbose for general usage).

            Show
            tjenness Tim Jenness added a comment - I'm not entirely sold on the idea of the default situation being that no messages turn up other than warnings. To me, warnings indicate problems that we should try to solve rather than stuff that can usually be ignored. It seems like INFO is too verbose but if it's not possible to add an extra level between INFO and DEBUG then I'm at a bit of a loss how to proceed (the description for TRACE above sounds far too verbose for general usage).
            Hide
            tjenness Tim Jenness added a comment -

            Hsin-Fang Chiang can you clarify the reason why we can't add a VERBOSE between INFO and DEBUG? Can't we set VERBOSE = 15000 in lsst.log?

            Show
            tjenness Tim Jenness added a comment - Hsin-Fang Chiang can you clarify the reason why we can't add a VERBOSE between INFO and DEBUG? Can't we set VERBOSE = 15000 in lsst.log ?
            Hide
            salnikov Andy Salnikov added a comment -

            Tim Jenness, it is not that trivial, you also need to tell log4cxx about this new level (e.g. to be able to configure logging level via property file). Being Java-inspired log4cxx does not make that task very easy.

            Show
            salnikov Andy Salnikov added a comment - Tim Jenness , it is not that trivial, you also need to tell log4cxx about this new level (e.g. to be able to configure logging level via property file). Being Java-inspired log4cxx does not make that task very easy.
            Hide
            tjenness Tim Jenness added a comment -

            We do not seem to be converging. Flagging this.

            Show
            tjenness Tim Jenness added a comment - We do not seem to be converging. Flagging this.
            tjenness Tim Jenness made changes -
            Field Original Value New Value
            Status Proposed [ 10805 ] Flagged [ 10606 ]
            Hide
            rhl Robert Lupton added a comment -

            When we resolve this, I hope that technical difficulties with the logging system we chose will not be given significant weight.

            Show
            rhl Robert Lupton added a comment - When we resolve this, I hope that technical difficulties with the logging system we chose will not be given significant weight.
            tjenness Tim Jenness made changes -
            Assignee Robert Lupton [ rhl ] Kian-Tat Lim [ ktl ]
            Hide
            rowen Russell Owen added a comment -

            I like Tim Jenness's suggestion of adding a "verbose" level, leaving the default at "info", and changing some messages to level "verbose" so they are hidden by default.

            I agree with Robert Lupton that we should not let the limitations of the logging package get in the way of doing something reasonable (whatever that is). My personal fallback (a distant second) would be to leave the level at "info". I think setting the default level to "warning" is too draconian.

            Show
            rowen Russell Owen added a comment - I like Tim Jenness 's suggestion of adding a "verbose" level, leaving the default at "info", and changing some messages to level "verbose" so they are hidden by default. I agree with Robert Lupton that we should not let the limitations of the logging package get in the way of doing something reasonable (whatever that is). My personal fallback (a distant second) would be to leave the level at "info". I think setting the default level to "warning" is too draconian.
            Hide
            ktl Kian-Tat Lim added a comment -

            It sounds to me like this is mostly a matter of naming and that we could rename "DEBUG" to "VERBOSE" and "TRACE" to "DEBUG" (with the additional "TRACEn" levels still available for that functionality), if people really care that much about the names.

            Show
            ktl Kian-Tat Lim added a comment - It sounds to me like this is mostly a matter of naming and that we could rename "DEBUG" to "VERBOSE" and "TRACE" to "DEBUG" (with the additional "TRACEn" levels still available for that functionality), if people really care that much about the names.
            Hide
            rowen Russell Owen added a comment -

            My main desire is to keep the default level at INFO and apparently that will require increasing the verbosity level of some existing messages so they are not shown by default.

            I think Kian-Tat Lim is right: I'm not hearing a strong call to add more than two levels of increased verbosity above INFO. If so, I suggest renaming only if we think the current names are sufficiently confusing for new users to justify the work.

            Show
            rowen Russell Owen added a comment - My main desire is to keep the default level at INFO and apparently that will require increasing the verbosity level of some existing messages so they are not shown by default. I think Kian-Tat Lim is right: I'm not hearing a strong call to add more than two levels of increased verbosity above INFO. If so, I suggest renaming only if we think the current names are sufficiently confusing for new users to justify the work.
            Hide
            tjenness Tim Jenness added a comment -

            My view is that there is a huge mental gulf for people between "INFO" and "DEBUG" that will always lead to people erring towards using "INFO" on the basis that "this is not only useful for debugging". Names are really important here and "VERBOSE" has the right nuance as a step between the two.

            Show
            tjenness Tim Jenness added a comment - My view is that there is a huge mental gulf for people between "INFO" and "DEBUG" that will always lead to people erring towards using "INFO" on the basis that "this is not only useful for debugging". Names are really important here and "VERBOSE" has the right nuance as a step between the two.
            Hide
            rowen Russell Owen added a comment -

            Another small argument in favor of renaming: the relative verbosity of "DEBUG" and "TRACE" is not self-evident, so "INFO", "VERBOSE", "DEBUG" is probably easier to understand than "INFO", "DEBUG", "TRACE".

            Show
            rowen Russell Owen added a comment - Another small argument in favor of renaming: the relative verbosity of "DEBUG" and "TRACE" is not self-evident, so "INFO", "VERBOSE", "DEBUG" is probably easier to understand than "INFO", "DEBUG", "TRACE".
            tjenness Tim Jenness made changes -
            Remote Link This issue links to "Page (Confluence)" [ 14819 ]
            Hide
            ktl Kian-Tat Lim added a comment -

            It looks like renaming DEBUG to VERBOSE and TRACE to DEBUG will be just as hard if not harder than adding a VERBOSE level. So, much as I would rather discourage adding new custom levels, it looks like the best way to resolve this is to create a new VERBOSE level and move most of the current INFO messages to it.

            In any case, I would say that changing the default level from INFO to WARN is not desirable.

            Show
            ktl Kian-Tat Lim added a comment - It looks like renaming DEBUG to VERBOSE and TRACE to DEBUG will be just as hard if not harder than adding a VERBOSE level. So, much as I would rather discourage adding new custom levels, it looks like the best way to resolve this is to create a new VERBOSE level and move most of the current INFO messages to it. In any case, I would say that changing the default level from INFO to WARN is not desirable.
            Hide
            rowen Russell Owen added a comment -

            +1 to Kian-Tat Lim's most recent proposal. I don't know how much work it requires inside the log package but I like it because it is the least disruptive to all code that uses the log package. That will continue to run without change, and we can change the level of existing messages based on time and demand.

            Show
            rowen Russell Owen added a comment - +1 to Kian-Tat Lim 's most recent proposal. I don't know how much work it requires inside the log package but I like it because it is the least disruptive to all code that uses the log package. That will continue to run without change, and we can change the level of existing messages based on time and demand.
            tjenness Tim Jenness made changes -
            Link This issue is triggering DM-9226 [ DM-9226 ]
            Hide
            tjenness Tim Jenness added a comment -

            Adopted as stated in the commentary by Kian-Tat Lim: Adding a new VERBOSE logging level between INFO and DEBUG and not changing the default log level from INFO to WARN.

            Show
            tjenness Tim Jenness added a comment - Adopted as stated in the commentary by Kian-Tat Lim : Adding a new VERBOSE logging level between INFO and DEBUG and not changing the default log level from INFO to WARN.
            tjenness Tim Jenness made changes -
            Resolution Done [ 10000 ]
            Status Flagged [ 10606 ] Adopted [ 10806 ]
            Hide
            gpdf Gregory Dubois-Felsmann added a comment -

            It would be useful for the CmdLineActivator in the SuperTask system to allow individuals to set personal defaults for their preferred default logging visibility level.

            Show
            gpdf Gregory Dubois-Felsmann added a comment - It would be useful for the CmdLineActivator in the SuperTask system to allow individuals to set personal defaults for their preferred default logging visibility level.
            rowen Russell Owen made changes -
            Summary Change the default log level from INFO to WARN Add VERBOSE log level (was: Change the default log level from INFO to WARN)
            tjenness Tim Jenness made changes -
            Link This issue is triggering DM-30286 [ DM-30286 ]
            tjenness Tim Jenness made changes -
            Status Adopted [ 10806 ] Implemented [ 11105 ]
            Hide
            tjenness Tim Jenness added a comment -

            This is now supported in the lsst.utils.logging.LsstLogAdapter class, which is the logging class now associated with all Tasks. The verbose log level is also understood by pipetask. This was facilitated by the switch away from lsst.log to python logging.

            Show
            tjenness Tim Jenness added a comment - This is now supported in the lsst.utils.logging.LsstLogAdapter class, which is the logging class now associated with all Tasks. The verbose log level is also understood by pipetask. This was facilitated by the switch away from lsst.log to python logging.
            tjenness Tim Jenness made changes -
            Remote Link This issue links to "Page (Confluence)" [ 31544 ]

              People

              Assignee:
              ktl Kian-Tat Lim
              Reporter:
              rhl Robert Lupton
              Watchers:
              Andy Salnikov, Colin Slater, Gregory Dubois-Felsmann, Hsin-Fang Chiang, John Gates, John Parejko, John Swinbank, Kian-Tat Lim, Robert Lupton, Russell Owen, Tim Jenness
              Votes:
              0 Vote for this issue
              Watchers:
              11 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Planned End:

                  CI Builds

                  No builds found.