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

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