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

          rowen Russell Owen created issue -
          rowen Russell Owen made changes -
          Field Original Value New Value
          Description I tried to rebuild my stack to take advantage of the recent logging changes. The rebuild failed on obs_sdss with the following error in {{tests/testSelectSdssImages.py}} which appears to be a bug in the log package itself:

          {code}
          ======================================================================
          ERROR: testWholeSky (__main__.SelectSdssImagesTestCase)
          Test whole-sky search (slow so don't do much)
          ----------------------------------------------------------------------
          Traceback (most recent call last):
            File "tests/testSelectSdssImages.py", line 354, in testWholeSky
              expInfoList = task.run(coordList=coordList, filter=filter).exposureInfoList
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/pipe_base/12.0-10-gdb0b236/python/lsst/pipe/base/timer.py", line 121, in wrapper
              res = func(self, *args, **keyArgs)
            File "/Users/rowen/UW/LSST/lsstsw/build/obs_sdss/python/lsst/obs/sdss/selectSdssImages.py", line 267, in run
              self.log.info("queryStr=%r; dataTuple=%s" % (queryStr, dataTuple))
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 280, in info
              self._log(Log.INFO, fmt, *args)
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 296, in _log
              inspect.stack()[2][3], frame.f_lineno, fmt % args)
          TypeError: not enough arguments for format string
          {code}
          I tried to rebuild my stack on macOS 10.11 to take advantage of the recent logging changes. The rebuild failed on obs_sdss with the following error in {{tests/testSelectSdssImages.py}} which appears to be a bug in the log package itself:

          {code}
          ======================================================================
          ERROR: testWholeSky (__main__.SelectSdssImagesTestCase)
          Test whole-sky search (slow so don't do much)
          ----------------------------------------------------------------------
          Traceback (most recent call last):
            File "tests/testSelectSdssImages.py", line 354, in testWholeSky
              expInfoList = task.run(coordList=coordList, filter=filter).exposureInfoList
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/pipe_base/12.0-10-gdb0b236/python/lsst/pipe/base/timer.py", line 121, in wrapper
              res = func(self, *args, **keyArgs)
            File "/Users/rowen/UW/LSST/lsstsw/build/obs_sdss/python/lsst/obs/sdss/selectSdssImages.py", line 267, in run
              self.log.info("queryStr=%r; dataTuple=%s" % (queryStr, dataTuple))
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 280, in info
              self._log(Log.INFO, fmt, *args)
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 296, in _log
              inspect.stack()[2][3], frame.f_lineno, fmt % args)
          TypeError: not enough arguments for format string
          {code}
          rowen Russell Owen made changes -
          Description I tried to rebuild my stack on macOS 10.11 to take advantage of the recent logging changes. The rebuild failed on obs_sdss with the following error in {{tests/testSelectSdssImages.py}} which appears to be a bug in the log package itself:

          {code}
          ======================================================================
          ERROR: testWholeSky (__main__.SelectSdssImagesTestCase)
          Test whole-sky search (slow so don't do much)
          ----------------------------------------------------------------------
          Traceback (most recent call last):
            File "tests/testSelectSdssImages.py", line 354, in testWholeSky
              expInfoList = task.run(coordList=coordList, filter=filter).exposureInfoList
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/pipe_base/12.0-10-gdb0b236/python/lsst/pipe/base/timer.py", line 121, in wrapper
              res = func(self, *args, **keyArgs)
            File "/Users/rowen/UW/LSST/lsstsw/build/obs_sdss/python/lsst/obs/sdss/selectSdssImages.py", line 267, in run
              self.log.info("queryStr=%r; dataTuple=%s" % (queryStr, dataTuple))
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 280, in info
              self._log(Log.INFO, fmt, *args)
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 296, in _log
              inspect.stack()[2][3], frame.f_lineno, fmt % args)
          TypeError: not enough arguments for format string
          {code}
          I tried to rebuild my stack on macOS 10.11 to take advantage of the recent logging changes. The rebuild failed on obs_sdss with the following error in {{tests/testSelectSdssImages.py}} which appears to be a bug in the log package itself:

          {code}
          ======================================================================
          ERROR: testWholeSky (__main__.SelectSdssImagesTestCase)
          Test whole-sky search (slow so don't do much)
          ----------------------------------------------------------------------
          Traceback (most recent call last):
            File "tests/testSelectSdssImages.py", line 354, in testWholeSky
              expInfoList = task.run(coordList=coordList, filter=filter).exposureInfoList
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/pipe_base/12.0-10-gdb0b236/python/lsst/pipe/base/timer.py", line 121, in wrapper
              res = func(self, *args, **keyArgs)
            File "/Users/rowen/UW/LSST/lsstsw/build/obs_sdss/python/lsst/obs/sdss/selectSdssImages.py", line 267, in run
              self.log.info("queryStr=%r; dataTuple=%s" % (queryStr, dataTuple))
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 280, in info
              self._log(Log.INFO, fmt, *args)
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 296, in _log
              inspect.stack()[2][3], frame.f_lineno, fmt % args)
          TypeError: not enough arguments for format string
          {code}

          I inserted a pdb trace statement to see what was going on. Here are the values of the arguments to _log in logLib.py; in particular, note that {{args}} is an empty tuple:
          {code}
          level = 20000

          fmt = "queryStr='select run, rerun, camcol, field, filter, ra1, dec1, ra2, dec2, ra3, dec3, ra4, dec4, strip, psfWidth, sky, airmass, quality, isblacklisted \\nfrom SeasonFieldQuality_Test as ccdExp,\\n (select distinct fieldid\\n from SeasonFieldQuality_To_Htm10 as ccdHtm inner join scisql.Region\\n on (ccdHtm.htmId10 between scisql.Region.htmMin and scisql.Region.htmMax)\\n where ccdHtm.filter = %s) as idList\\nwhere ccdExp.fieldid = idList.fieldid and filter = %s'; dataTuple=('g', 'g')"
          ipdb> args
          self = <lsst.log.logLib.Log; proxy of <Swig Object of type 'lsst::log::Log *' at 0x1156dbb70> >
          level = 20000
          fmt = queryStr='select run, rerun, camcol, field, filter, ra1, dec1, ra2, dec2, ra3, dec3, ra4, dec4, strip, psfWidth, sky, airmass, quality, isblacklisted \nfrom SeasonFieldQuality_Test as ccdExp,\n (select distinct fieldid\n from SeasonFieldQuality_To_Htm10 as ccdHtm inner join scisql.Region\n on (ccdHtm.htmId10 between scisql.Region.htmMin and scisql.Region.htmMax)\n where ccdHtm.filter = %s) as idList\nwhere ccdExp.fieldid = idList.fieldid and filter = %s'; dataTuple=('g', 'g')

          args = ()

          {code}
          tjenness Tim Jenness made changes -
          Component/s obs_sdss [ 10763 ]
          tjenness Tim Jenness made changes -
          Labels SciencePipelines
          rowen Russell Owen made changes -
          Summary error: not enough arguments for format string Logging system sensitive to %s in string
          tjenness Tim Jenness made changes -
          Comment [ You are right that it's a major interface change for {{%}} to suddenly become magic between {{pex_logging}} and {{log}}. I'm not entirely sure that was considered before the bulk migration. Having to explicitly double up {{%}} characters before sending them to the logger seems painful and it's not entirely clear that allowing a {{None}} as the 2nd argument would be much better.
          {code:python}
          self.log.info("Do not expand %s", None)
          {code}
          vs
          {code:python}
          self.log.info("Do not expand %%s")
          {code}
          I'm not sure what the best way is to switch off string expansion in {{log}} without having that extra argument or a new method ({{infon}}?). You don't always know if the thing you are logging includes strings that Python might interpret as string formatting.

          I had also wondered why we needed to make all the changes to defer the string formatting, it's not any more efficient because it's still all happening in Python.

          Maybe the remaining {{%s}} is messing up the C++ layer? ]
          rowen Russell Owen made changes -
          Story Points 2
          Team Alert Production [ 10300 ]
          Assignee Hsin-Fang Chiang [ hchiang2 ] Russell Owen [ rowen ]
          Description I tried to rebuild my stack on macOS 10.11 to take advantage of the recent logging changes. The rebuild failed on obs_sdss with the following error in {{tests/testSelectSdssImages.py}} which appears to be a bug in the log package itself:

          {code}
          ======================================================================
          ERROR: testWholeSky (__main__.SelectSdssImagesTestCase)
          Test whole-sky search (slow so don't do much)
          ----------------------------------------------------------------------
          Traceback (most recent call last):
            File "tests/testSelectSdssImages.py", line 354, in testWholeSky
              expInfoList = task.run(coordList=coordList, filter=filter).exposureInfoList
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/pipe_base/12.0-10-gdb0b236/python/lsst/pipe/base/timer.py", line 121, in wrapper
              res = func(self, *args, **keyArgs)
            File "/Users/rowen/UW/LSST/lsstsw/build/obs_sdss/python/lsst/obs/sdss/selectSdssImages.py", line 267, in run
              self.log.info("queryStr=%r; dataTuple=%s" % (queryStr, dataTuple))
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 280, in info
              self._log(Log.INFO, fmt, *args)
            File "/Users/rowen/UW/LSST/lsstsw/stack/DarwinX86/log/12.0-4-gbdaee9d/python/lsst/log/logLib.py", line 296, in _log
              inspect.stack()[2][3], frame.f_lineno, fmt % args)
          TypeError: not enough arguments for format string
          {code}

          I inserted a pdb trace statement to see what was going on. Here are the values of the arguments to _log in logLib.py; in particular, note that {{args}} is an empty tuple:
          {code}
          level = 20000

          fmt = "queryStr='select run, rerun, camcol, field, filter, ra1, dec1, ra2, dec2, ra3, dec3, ra4, dec4, strip, psfWidth, sky, airmass, quality, isblacklisted \\nfrom SeasonFieldQuality_Test as ccdExp,\\n (select distinct fieldid\\n from SeasonFieldQuality_To_Htm10 as ccdHtm inner join scisql.Region\\n on (ccdHtm.htmId10 between scisql.Region.htmMin and scisql.Region.htmMax)\\n where ccdHtm.filter = %s) as idList\\nwhere ccdExp.fieldid = idList.fieldid and filter = %s'; dataTuple=('g', 'g')"
          ipdb> args
          self = <lsst.log.logLib.Log; proxy of <Swig Object of type 'lsst::log::Log *' at 0x1156dbb70> >
          level = 20000
          fmt = queryStr='select run, rerun, camcol, field, filter, ra1, dec1, ra2, dec2, ra3, dec3, ra4, dec4, strip, psfWidth, sky, airmass, quality, isblacklisted \nfrom SeasonFieldQuality_Test as ccdExp,\n (select distinct fieldid\n from SeasonFieldQuality_To_Htm10 as ccdHtm inner join scisql.Region\n on (ccdHtm.htmId10 between scisql.Region.htmMin and scisql.Region.htmMax)\n where ccdHtm.filter = %s) as idList\nwhere ccdExp.fieldid = idList.fieldid and filter = %s'; dataTuple=('g', 'g')

          args = ()

          {code}
          There are two bugs in the log package:

          log.info("%s") results in:
          {code}
          TypeError: not enough arguments for format string
          {code}
          this is because Log._log is defined with this line:
          {code}
          self.log(level, os.path.split(frame.f_code.co_filename)[1],
                               inspect.stack()[2][3], frame.f_lineno, fmt % args)
          {code}
          and in this case args is an empty tuple. A trivial fix is to replace this with:
          {code}
          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)
          {code}

          However, doing so exposes another bug. The following will segfault:
          {code}
          log.log(2000, "foo", "bar", 5, "%s")
          {code}
          This is because Log.log is extended in logLib.i as follows:
          {code}
              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());
          {code}
          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:
          {code}
              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());
          {code}

          In addition, this requires the first fix to be changed to call {{logMsg}} instead of {{log}}
          rowen Russell Owen made changes -
          Comment [ The Log object supports these two calls:
          {code}
              void log(log4cxx::LevelPtr level,
                       log4cxx::spi::LocationInfo const& location,
                       char const* fmt, ...);
              void logMsg(log4cxx::LevelPtr level,
                          log4cxx::spi::LocationInfo const& location,
                          std::string const& msg);
          {code}
          I think the Python wrapper should be calling the second one instead of the first, e.g. in logLib.i, change:
          {code}
              def _log(self, level, fmt, *args):
                  if self.isEnabledFor(level):
                      frame = inspect.currentframe().f_back # calling method
                      frame = frame.f_back # original log location
                      self.log(level, os.path.split(frame.f_code.co_filename)[1],
                               inspect.stack()[2][3], frame.f_lineno, fmt % args)
          {code}
          to this:
          {code}
              def _log(self, level, fmt, *args):
                  if self.isEnabledFor(level):
                      frame = inspect.currentframe().f_back # calling method
                      frame = frame.f_back # original log location
                      msg = fmt % args if args else fmt # new line
                      self.logMsg(level, os.path.split(frame.f_code.co_filename)[1],
                               inspect.stack()[2][3], frame.f_lineno, msg) # change log to logMsg and fmt % args to msg
          {code}
          However, that isn't quite right. According to SWIG self.log supports {{lsst::log::Log::log(int,std::string const &,std::string const &,unsigned int,std::string const &)
          }} (note the string at the end) which is what's being used. But no such method exists for {{self.logMsg}}.

          I also confirmed that logging a message containing %s causes a failure. In {{logLib.py}} the following segfaulted: {{self.log(2000, "foo", "foo", 5, "foo %s bar")}} which is about as simple as it gets. ]
          rowen Russell Owen made changes -
          Comment [ I pushed an attempted fix. The additional change to wrap logMsg instead of log is a trivial change to logLib.i ]
          rowen Russell Owen made changes -
          Comment [ It is not complete in that unit tests need updating and in any case a test should be added to make sure a message containing %s can safely be logged. But it's a start. ]
          rowen Russell Owen made changes -
          Comment [ Here is a trivial way to reproduce the problem, though it does not show how to fix it:
          {code}
          import lsst.log
          >>> log = lsst.log.Log()
          >>> log.log(2000, "", "", 5, "foo %s bar")
          {code}

          I think the python wrapper is simply wrong for {{lsst::log::Log::log(int,std::string const &,std::string const &,unsigned int,std::string const &)}}; I suspect it should be eliminated and replaced by the same thing that wraps logMsg. ]
          rowen Russell Owen made changes -
          Status To Do [ 10001 ] In Progress [ 3 ]
          rowen Russell Owen made changes -
          Reviewers Hsin-Fang Chiang [ hchiang2 ]
          Status In Progress [ 3 ] In Review [ 10004 ]
          hchiang2 Hsin-Fang Chiang made changes -
          Status In Review [ 10004 ] Reviewed [ 10101 ]
          rowen Russell Owen made changes -
          Epic Link DM-7362 [ 26448 ]
          rowen Russell Owen made changes -
          Resolution Done [ 10000 ]
          Status Reviewed [ 10101 ] Done [ 10002 ]

            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