# 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

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.
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.
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.
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).
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.
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.
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.
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.

#### People

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