# Python logging with string formatting issue

**URL:** <https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366>\
**Category:** Development\
**Created:** [July 3, 2018, 5:58pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366 "2018-07-03T17:58:03Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![jamesobutler](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/jamesobutler/32/7511_2.png) [@jamesobutler](https://discourse.slicer.org/u/jamesobutler)\
**Post date:** [July 3, 2018, 5:58pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/1 "2018-07-03T17:58:03Z")

</div>

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?

```nohighlight
[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](https://github.com/Slicer/Slicer/blob/0d281895d52ca92fb52f2cedbff544f2b87ebc29/Utilities/Scripts/SlicerWizard/ExtensionWizard.py) where I would expect this same issue to happen.

---

<div class="post-metadata">

**Author:** ![lassoan](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/lassoan/32/13_2.png) [@lassoan](https://discourse.slicer.org/u/lassoan)\
**Post date:** [July 3, 2018, 7:02pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/2 "2018-07-03T19:02:36Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![jamesobutler](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/jamesobutler/32/7511_2.png) [@jamesobutler](https://discourse.slicer.org/u/jamesobutler)\
**Post date:** [July 3, 2018, 7:21pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/3 "2018-07-03T19:21:14Z")

</div>

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

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

```

instead of

```python
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](http://www.python.org/dev/peps/pep-0282/).

---

<div class="post-metadata">

**Author:** ![lassoan](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/lassoan/32/13_2.png) [@lassoan](https://discourse.slicer.org/u/lassoan)\
**Post date:** [July 3, 2018, 7:44pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/4 "2018-07-03T19:44:09Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![jamesobutler](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/jamesobutler/32/7511_2.png) [@jamesobutler](https://discourse.slicer.org/u/jamesobutler)\
**Post date:** [July 3, 2018, 7:55pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/5 "2018-07-03T19:55:54Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![lassoan](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/lassoan/32/13_2.png) [@lassoan](https://discourse.slicer.org/u/lassoan)\
**Post date:** [July 3, 2018, 8:33pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/6 "2018-07-03T20:33:13Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![jamesobutler](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/jamesobutler/32/7511_2.png) [@jamesobutler](https://discourse.slicer.org/u/jamesobutler)\
**Post date:** [July 3, 2018, 9:13pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/7 "2018-07-03T21:13:59Z")

</div>

Sure, I will definitely take a look @lassoan

---

<div class="post-metadata">

**Author:** ![jamesobutler](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/jamesobutler/32/7511_2.png) [@jamesobutler](https://discourse.slicer.org/u/jamesobutler)\
**Post date:** [July 3, 2018, 10:43pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/8 "2018-07-03T22:43:22Z")

</div>

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

```nohighlight
[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](https://github.com/Slicer/Slicer/blob/3ea26dae3e461899f8ecf51ec7ae02f7bab10d15/Base/Python/slicer/slicerqt.py#L72) in slicerqt.py. Simplifying that line to the following below appears to remove those extra elements in the message. Is this the appropriate solution?

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

```

```nohighlight
[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

```

---

<div class="post-metadata">

**Author:** ![lassoan](https://sea2.discourse-cdn.com/flex002/user_avatar/discourse.slicer.org/lassoan/32/13_2.png) [@lassoan](https://discourse.slicer.org/u/lassoan)\
**Post date:** [April 6, 2023, 6:10pm UTC](https://discourse.slicer.org/t/python-logging-with-string-formatting-issue/3366/9 "2023-04-06T18:10:03Z")

</div>

A post was split to a new topic: [How to change log message prefix](https://discourse.slicer.org/t/how-to-change-log-message-prefix/28784)