# Logging system sensitive to %s in string

XMLWordPrintable

## Details

• Type: Bug
• Status: Done
• Resolution: Done
• Fix Version/s: None
• Component/s:
• Labels:
• Story Points:
2
• Team:

## 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

## Activity

Russell Owen created issue -
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
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
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
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
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.
 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 = > 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}
 Component/s obs_sdss [ 10763 ]
 Labels SciencePipelines
Hide
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
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
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
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
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
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.
 Summary error: not enough arguments for format string Logging system sensitive to %s in string
Hide
Tim Jenness added a comment -

Yes, I agree with that suggested change.

Show
Tim Jenness added a comment - Yes, I agree with that suggested change.
 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
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
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
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
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
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
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).
 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 = > 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}}
 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. ]
 Comment [ I pushed an attempted fix. The additional change to wrap logMsg instead of log is a trivial change to logLib.i ]
 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. ]
 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
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
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.
 Status To Do [ 10001 ] In Progress [ 3 ]
Hide
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
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.
 Reviewers Hsin-Fang Chiang [ hchiang2 ] Status In Progress [ 3 ] In Review [ 10004 ]
Hide
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
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
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
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
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
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
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
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.
 Status In Review [ 10004 ] Reviewed [ 10101 ]
 Epic Link DM-7362 [ 26448 ]
Hide
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
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.
 Resolution Done [ 10000 ] Status Reviewed [ 10101 ] Done [ 10002 ]

## People

• Assignee:
Russell Owen
Reporter:
Russell Owen
Reviewers:
Hsin-Fang Chiang
Watchers:
Hsin-Fang Chiang, Russell Owen, Tim Jenness