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

Logging system sensitive to %s in string

    Details

      Description

      There are two bugs in the log package:

      log.info("%s") results in:

      TypeError: not enough arguments for format string
      

      this is because Log._log is defined with this line:

      self.log(level, os.path.split(frame.f_code.co_filename)[1],
                           inspect.stack()[2][3], frame.f_lineno, fmt % args)
      

      and in this case args is an empty tuple. A trivial fix is to replace this with:

      msg = fmt % args if args else fmt
      self.log(level, os.path.split(frame.f_code.co_filename)[1],
                           inspect.stack()[2][3], frame.f_lineno, msg)
      

      However, doing so exposes another bug. The following will segfault:

      log.log(2000, "foo", "bar", 5, "%s")
      

      This is because Log.log is extended in logLib.i as follows:

          void log(int level, std::string const& filename,
                   std::string const& funcname, unsigned int lineno,
                   std::string const& msg) {
              self->log(log4cxx::Level::toLevel(level),
                        log4cxx::spi::LocationInfo(filename.c_str(), funcname.c_str(), lineno),
                        msg.c_str());
      

      and the version of Log.log it calls expects additional format arguments. In general the log package seems to use logMsg when no %s formatting is wanted, and log when such formatting is wanted, so I propose to fix this using:

          void logMsg(int level, std::string const& filename,
                   std::string const& funcname, unsigned int lineno,
                   std::string const& msg) {
              self->logMsg(log4cxx::Level::toLevel(level),
                        log4cxx::spi::LocationInfo(filename.c_str(), funcname.c_str(), lineno),
                        msg.c_str());
      

      In addition, this requires the first fix to be changed to call logMsg instead of log

        Attachments

          Activity

          Hide
          rowen Russell Owen added a comment -

          Thank you to Hsin-Fang Chiang and Tim Jenness for the fast review, and on a 3 day weekend no less!

          I cleaned up the indentation issues noted by Tim Jenness and rebased the commits (including Hsin-Fang Chiang's test improvement) so that:

          • The test for logging messages containing "%s" is part of the same commit that fixes the bugs
          • Removed a test result file that I accidentally added
          • Updated .gitignore to hide tests/testLog and remove an obsolete entry

          I will merge to master after a final successful Jenkins run.

          Show
          rowen Russell Owen added a comment - Thank you to Hsin-Fang Chiang and Tim Jenness for the fast review, and on a 3 day weekend no less! I cleaned up the indentation issues noted by Tim Jenness and rebased the commits (including Hsin-Fang Chiang 's test improvement) so that: The test for logging messages containing "%s" is part of the same commit that fixes the bugs Removed a test result file that I accidentally added Updated .gitignore to hide tests/testLog and remove an obsolete entry I will merge to master after a final successful Jenkins run.
          Hide
          hchiang2 Hsin-Fang Chiang added a comment -

          Your changes look fine to me, with some comments from Tim Jenness on the PR (indentation, the binary tests/testLog, etc). I agree with using logMsg as doing string interpolation more than once really does not make sense. Thanks for fixing it.

          I added a commit to log through the logger in the newly added test.

          lsst.log.info("this logs to the default root logger")
          

          is fine but I find logging to a logger less confusing as a logger is available in that test.

          Show
          hchiang2 Hsin-Fang Chiang added a comment - Your changes look fine to me, with some comments from Tim Jenness on the PR (indentation, the binary tests/testLog, etc). I agree with using logMsg as doing string interpolation more than once really does not make sense. Thanks for fixing it. I added a commit to log through the logger in the newly added test. lsst.log.info( "this logs to the default root logger" ) is fine but I find logging to a logger less confusing as a logger is available in that test.
          Hide
          hchiang2 Hsin-Fang Chiang added a comment -

          In C++, LOGL_WARN(logger, "This is WARN %s"); gives

          unknown location:0: fatal error: in "log_stream": memory access violation at address: 0xfffffff0: no mapping at fault address

          But to log something with % in the string, one can use the iostream-style formatting.
          e.g. LOGLS_WARN(logger, "This is WARN " << "%s"); is fine.

          Show
          hchiang2 Hsin-Fang Chiang added a comment - In C++, LOGL_WARN(logger, "This is WARN %s"); gives unknown location:0: fatal error: in "log_stream": memory access violation at address: 0xfffffff0: no mapping at fault address But to log something with % in the string, one can use the iostream-style formatting. e.g. LOGLS_WARN(logger, "This is WARN " << "%s"); is fine.
          Hide
          rowen Russell Owen added a comment -

          I have one remaining concern: is C++ logging subject to the same segfault, e.g. if one provides a format string with a mis-matched number of data arguments? If so, is there some way to raise an exception, instead? I suspect our code contains many log messages that will rarely or never be printed, and I'd hate to have those able to cause a segfault.

          Show
          rowen Russell Owen added a comment - I have one remaining concern: is C++ logging subject to the same segfault, e.g. if one provides a format string with a mis-matched number of data arguments? If so, is there some way to raise an exception, instead? I suspect our code contains many log messages that will rarely or never be printed, and I'd hate to have those able to cause a segfault.
          Hide
          tjenness Tim Jenness added a comment -

          Regarding Jenkins, I think that there must be only one place that uses %s in a log message using the new logger and that test is skipped on Jenkins because Jenkins does not know how to connect to lsst-db.

          Show
          tjenness Tim Jenness added a comment - Regarding Jenkins, I think that there must be only one place that uses %s in a log message using the new logger and that test is skipped on Jenkins because Jenkins does not know how to connect to lsst-db .

            People

            • Assignee:
              rowen Russell Owen
              Reporter:
              rowen Russell Owen
              Reviewers:
              Hsin-Fang Chiang
              Watchers:
              Hsin-Fang Chiang, Russell Owen, Tim Jenness
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Summary Panel