Python logging with string formatting issue

Development
1

I’m having issues when writing a debug log message in python while also using the % string formatting operator. It gets interpreted correctly at the info log level, but not at the debug level.

Any idea why the behavior is like this?

[DEBUG][Qt] 03.07.2018 13:07:23 [] (unknown:0) - Python console user input: a="string"
[DEBUG][Python] 03.07.2018 13:07:36 [Python] (<console>:1) - This is a %s
[DEBUG][Qt] 03.07.2018 13:07:36 [] (unknown:0) - Python console user input: logging.debug("This is a %s", a)
[INFO][Python] 03.07.2018 13:07:40 [Python] (<console>:1) - This is a %s
[DEBUG][Qt] 03.07.2018 13:07:40 [] (unknown:0) - Python console user input: logging.info("This is a %s", a)
[INFO][Stream] 03.07.2018 13:07:40 [] (unknown:0) - This is a string

There is similar python debug logging in the Slicer repo within ExtensionWizard.py where I would expect this same issue to happen.

2

All parameters are forwarded to the log formatter. It is just a coincidence that info formatter uses the additional argument. If you want to log a string then the proper syntax is:

a="something"
logging.debug("This is a %s" % a)
logging.info("This is a %s" % a)
3

I’m using pylint as one of my linters and it explicitly warned to do it as:

logging.debug("This is a %s", a)

instead of

logging.debug("This is a %s" % a)

logging-not-lazy (W1201):
Specify string format arguments as logging function parameters Used when a logging statement has a call form of “logging.(format_string % (format_args…))”. Such calls should leave string interpolation to the logging method itself and be written “logging.(format_string, format_args…)” so that the program may avoid incurring the cost of the interpolation in those cases in which no message will be logged. For more, see PEP 282 – A Logging System | peps.python.org.

4

I see, thanks for the additional information. It’s true that by passing the format specifier and arguments separately, string formatting can be avoided when not needed. Probably we can make the debug formatter to use all the arguments, too. I’ll have a look.

1 Like
5

Thanks for looking into this Andras!

I’ve started to actually look at what my linters say to make sure I’m following python standards better.

6

Please have a look at slicerqt.py. It uses SlicerApplicationLogHandler class to create a CTK log entry from a Python log record.

By changing the implementation to something like this, the log will contain the full formatted string:

#-----------------------------------------------------------------------------
class SlicerApplicationLogHandler(logging.Handler):
  """
  Writes logging records to Slicer application log.
  """
  def __init__(self):
    logging.Handler.__init__(self)
    if hasattr(ctk, 'ctkErrorLogLevel'):
      self.pythonToCtkLevelConverter = {
        logging.DEBUG : ctk.ctkErrorLogLevel.Debug,
        logging.INFO : ctk.ctkErrorLogLevel.Info,
        logging.WARNING : ctk.ctkErrorLogLevel.Warning,
        logging.ERROR : ctk.ctkErrorLogLevel.Error }
    self.origin = "Python"
    self.category = "Python"
  def emit(self, record):
    try:
      msg = self.format(record)
      context = ctk.ctkErrorLogContext()
      context.setCategory(self.category)
      context.setLine(record.lineno)
      context.setFile(record.pathname)
      context.setFunction(record.funcName)
      context.setMessage(msg)
      threadId = "{0}({1})".format(record.threadName, record.thread)
      slicer.app.errorLogModel().addEntry(qt.QDateTime.currentDateTime(), threadId,
        self.pythonToCtkLevelConverter[record.levelno], self.origin, context, msg)
    except:
      self.handleError(record)

However, this would log the log level, file name, and line number in the log message.

@jamesobutler Could you check how the formatting can be changed to avoid adding log level, file name, and line number in the message?

7

Sure, I will definitely take a look @lassoan

8

@lassoan
So with your update I can confirm it logs the full formatted string at the debug level:

[DEBUG][Qt] 03.07.2018 18:30:40 [] (unknown:0) - Python console user input: a="string"
[DEBUG][Python] 03.07.2018 18:30:51 [Python] (<console>:1) - DEBUG: This is a string (<console>:1)
[DEBUG][Qt] 03.07.2018 18:30:51 [] (unknown:0) - Python console user input: logging.debug("This is a %s", a)
[INFO][Python] 03.07.2018 18:30:55 [Python] (<console>:1) - INFO: This is a string (<console>:1)
[DEBUG][Qt] 03.07.2018 18:30:55 [] (unknown:0) - Python console user input: logging.info("This is a %s", a)
[INFO][Stream] 03.07.2018 18:30:55 [] (unknown:0) - This is a string

The log formats with log level, file name and line number because of here in slicerqt.py. Simplifying that line to the following below appears to remove those extra elements in the message. Is this the appropriate solution?

applicationLogHandler.setFormatter(logging.Formatter('%(message)s'))

[DEBUG][Qt] 03.07.2018 18:22:55 [] (unknown:0) - Python console user input: a="string"
[DEBUG][Python] 03.07.2018 18:23:07 [Python] (<console>:1) - This is a string
[DEBUG][Qt] 03.07.2018 18:23:07 [] (unknown:0) - Python console user input: logging.debug("This is a %s", a)
[INFO][Python] 03.07.2018 18:23:11 [Python] (<console>:1) - This is a string
[DEBUG][Qt] 03.07.2018 18:23:11 [] (unknown:0) - Python console user input: logging.info("This is a %s", a)
[INFO][Stream] 03.07.2018 18:23:11 [] (unknown:0) - This is a string
9

A post was split to a new topic: How to change log message prefix