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.

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.

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.

Yes, I agree with that suggested change.

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?

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?

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

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.

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.

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.

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.

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.

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.

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.