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

          It's not a bug in log. The problem is that queryStr contains % symbols and the string passed to log.info has already had its formatting expanded to a single string object but that string object now contains % and the logger tries to expand those again with a string formatter. This is why pipe_tasks recently had lots of commits to defer the string formatting to the log package. The fix is to change the self.log.info line that is failing to use the new style:

          self.log.info("queryStr=%r; dataTuple=%s", queryStr, dataTuple)
          

          This subtle change may cause problems elsewhere until all the code understands where string format expansion is meant to occur.

          Show
          tjenness Tim Jenness added a comment - It's not a bug in log . The problem is that queryStr contains % symbols and the string passed to log.info has already had its formatting expanded to a single string object but that string object now contains % and the logger tries to expand those again with a string formatter. This is why pipe_tasks recently had lots of commits to defer the string formatting to the log package. The fix is to change the self.log.info line that is failing to use the new style: self.log.info("queryStr=%r; dataTuple=%s", queryStr, dataTuple) This subtle change may cause problems elsewhere until all the code understands where string format expansion is meant to occur.
          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
          Hide
          rowen Russell Owen added a comment - - edited

          I think it is a bug that the logger cannot reliably print a pre-formatted string. if no arguments are provided then the logger has no business trying to %-format the string. That is a dangerous thing to do! This string does intrinsically contain %s.

          I thought the main reason why so much code switched to having the logger format the string is that it is more efficient; if the log message is not shown then the formatting operation is not performed.

          Worse, when I change the code to pass the arguments (so that the logger can format them) I get a segfault when the code attempts to log this same message. All the arguments to self.log in logLib.py look fine (I have individually evaluated each of them in pdb) but when pdb tries to run the following it segfaults:

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

          with the following arguments:

          level = 2000
          os.path.split(frame.f_code.co_filename)[1] = `selectSdssImages.py`
          inspect.stack()[2][3] = 'onecmd'
          frame.f_lineno = 268
          fmt % args = "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')"
          

          So I wonder if passing the %s further down is causing problems.

          Show
          rowen Russell Owen added a comment - - edited I think it is a bug that the logger cannot reliably print a pre-formatted string. if no arguments are provided then the logger has no business trying to %-format the string. That is a dangerous thing to do! This string does intrinsically contain %s . I thought the main reason why so much code switched to having the logger format the string is that it is more efficient; if the log message is not shown then the formatting operation is not performed. Worse, when I change the code to pass the arguments (so that the logger can format them) I get a segfault when the code attempts to log this same message. All the arguments to self.log in logLib.py look fine (I have individually evaluated each of them in pdb) but when pdb tries to run the following it segfaults: self.log(level, os.path.split(frame.f_code.co_filename)[1], inspect.stack()[2][3], frame.f_lineno, fmt % args) with the following arguments: level = 2000 os.path.split(frame.f_code.co_filename)[1] = `selectSdssImages.py` inspect.stack()[2][3] = 'onecmd' frame.f_lineno = 268 fmt % args = "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')" So I wonder if passing the %s further down is causing problems.
          Hide
          tjenness Tim Jenness added a comment - - edited

          Actually, sorry I'm a bit slow. You are right, we just change that fmt % args code in the _log method so that it only does the % if there are any items in args.

          Show
          tjenness Tim Jenness added a comment - - edited Actually, sorry I'm a bit slow. You are right, we just change that fmt % args code in the _log method so that it only does the % if there are any items in args .
          Hide
          rowen Russell Owen added a comment -

          My suggestion for not % formatting unless there are arguments to format is:

          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)
          

          That leaves the old interface, while still giving the advantage of not formatting unless the message is actually wanted.

          However, the segfault is more serious. I'm also really puzzled why this did not show up in Jenkins or on Hsin-Fang Chiang's mac when she tried it just now.

          Show
          rowen Russell Owen added a comment - My suggestion for not % formatting unless there are arguments to format is: 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) That leaves the old interface, while still giving the advantage of not formatting unless the message is actually wanted. However, the segfault is more serious. I'm also really puzzled why this did not show up in Jenkins or on Hsin-Fang Chiang 's mac when she tried it just now.
          rowen Russell Owen made changes -
          Summary error: not enough arguments for format string Logging system sensitive to %s in string
          Hide
          tjenness Tim Jenness added a comment -

          Yes, I agree with that suggested change.

          Show
          tjenness Tim Jenness added a comment - Yes, I agree with that suggested change.
          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? ]
          Hide
          rowen Russell Owen added a comment -

          I wonder if self.log is calling a C/C++ function that also does lazy formatting (e.g. fmt, arg1, arg2, ...). If so, is there a different C/C++ function that could be called that does no formatting?

          Show
          rowen Russell Owen added a comment - I wonder if self.log is calling a C/C++ function that also does lazy formatting (e.g. fmt, arg1, arg2, ...). If so, is there a different C/C++ function that could be called that does no formatting?
          Hide
          hchiang2 Hsin-Fang Chiang added a comment -

          Sorry.. I'm still catching up with the messages. I mistakenly told Russell Owen that tests were passed on my mac while they were all skipped. Could that be the case in the CI?

          Show
          hchiang2 Hsin-Fang Chiang added a comment - Sorry.. I'm still catching up with the messages. I mistakenly told Russell Owen that tests were passed on my mac while they were all skipped. Could that be the case in the CI?
          Hide
          tjenness Tim Jenness added a comment - - edited

          Yes, if we know that the Python layer has already done all the expected string interpolation we should definitely not be calling a C++ logging routine that will then try to also do string interpolation.

          Hsin-Fang Chiang thank you for demonstrating the need for rich test reporting metrics (including skip counts).

          Show
          tjenness Tim Jenness added a comment - - edited Yes, if we know that the Python layer has already done all the expected string interpolation we should definitely not be calling a C++ logging routine that will then try to also do string interpolation. Hsin-Fang Chiang thank you for demonstrating the need for rich test reporting metrics (including skip counts).
          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. ]
          Hide
          rowen Russell Owen added a comment -

          I pushed a fix and am running it Jenkins as https://ci.lsst.codes/job/stack-os-matrix/label=centos-7,python=py2/15337//console
          I also edited the description to fully explain what is going on; unfortunately that change makes the comments that follow rather confusing (though I deleted some of mine that were rendered redundant by the new description).

          I remain puzzled why this bug was not exposed when running Jenkins.

          Show
          rowen Russell Owen added a comment - I pushed a fix and am running it Jenkins as https://ci.lsst.codes/job/stack-os-matrix/label=centos-7,python=py2/15337//console I also edited the description to fully explain what is going on; unfortunately that change makes the comments that follow rather confusing (though I deleted some of mine that were rendered redundant by the new description). I remain puzzled why this bug was not exposed when running Jenkins.
          rowen Russell Owen made changes -
          Status To Do [ 10001 ] In Progress [ 3 ]
          Hide
          rowen Russell Owen added a comment -

          Done (with a final Jenkins run in progress).

          I renamed the tests from logTest.cc/py to testLog.cc/py and made a few trivial cleanups to testLog.py (including a # noqa on a long line that is justifiably too long to block a flake8 warning).

          If you are unhappy with renaming the Log override log(level, str, str, line #, msg) to logMsg, that can easily be changed back. I did this because it appears that logMsg is the way to log a pre-formatted message, but I am not an expert on the log package.

          Show
          rowen Russell Owen added a comment - Done (with a final Jenkins run in progress). I renamed the tests from logTest.cc/py to testLog.cc/py and made a few trivial cleanups to testLog.py (including a # noqa on a long line that is justifiably too long to block a flake8 warning). If you are unhappy with renaming the Log override log(level, str, str, line #, msg) to logMsg , that can easily be changed back. I did this because it appears that logMsg is the way to log a pre-formatted message, but I am not an expert on the log package.
          rowen Russell Owen made changes -
          Reviewers Hsin-Fang Chiang [ hchiang2 ]
          Status In Progress [ 3 ] In Review [ 10004 ]
          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 .
          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
          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
          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.
          hchiang2 Hsin-Fang Chiang made changes -
          Status In Review [ 10004 ] Reviewed [ 10101 ]
          rowen Russell Owen made changes -
          Epic Link DM-7362 [ 26448 ]
          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.
          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