Unexpected logging exceptions when using logging module + rotating file handlers

Description

Using the API in combination with the logging module + RotatingFileHandler throws exceptions like TypeError: not all arguments converted during string formatting and many others as seen below.

Seen on:

Windows 11 Pro 64-bit version 10.0.22000 Build 22000
Python 3.10.4
Inventree API v 0.6.0

Expected Behavior

No exceptions occur when using the API in combination with the logging module configured with a rotating file handler, all module-internal log messages are written to the log file.

Actual Behavior

The stdout is spammed with stack traces complaining abound some string formatting problems as seen in the example down below. The messages that cause these exceptions are not logged to the log file.

Despite this, the API works just fine and returns the requested data from the Inventree server.

How to reproduce

Setup the logging module with a rotating file handler
Create an Inventree API endpoint with the class InvenTreeAPI
Use the API
Check the console output on stdout

Or use this minimum working example to reproduce the behavior:

import logging
from logging.handlers import RotatingFileHandler
from inventree.api import InvenTreeAPI

Domain = "https://my.inventree.instance.tld"
User = "inventree"
Passwd = "mysecurepassword"

# 1. Initialize logging module
format = logging.Formatter("%(asctime)s - [%(levelname)s] - %(name)s - (%(filename)s).%(funcName)s(%(lineno)d) - %(message)s")

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)

file_handler = RotatingFileHandler("mylog.log", maxBytes = 10e6, backupCount = 1)
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(format)
logger.addHandler(file_handler)

# 2. Create Inventree API endpoint
Api = InvenTreeAPI(Domain, username=User, password=Passwd, verbose=True)

# 3. Use it
query = f"part/50/"
logger.debug(f'Requesting API at { query }')
result = Api.get(query)
logger.debug(f'Done!')

This MWE produces the following log output:

2022-04-12 22:55:18,561 - [INFO] - inventree - (api.py).__init__(60) - Connecting to server: https://my.inventree.instance.tld/
2022-04-12 22:55:18,561 - [INFO] - inventree - (api.py).testServer(97) - Checking InvenTree server connection...
2022-04-12 22:55:18,563 - [DEBUG] - urllib3.connectionpool - (connectionpool.py)._new_conn(1001) - Starting new HTTPS connection (1): my.inventree.instance.tld:443
2022-04-12 22:55:18,670 - [DEBUG] - urllib3.connectionpool - (connectionpool.py)._make_request(456) - https://my.inventree.instance.tld:443 "GET /api/ HTTP/1.1" 200 119
2022-04-12 22:55:18,671 - [INFO] - inventree - (api.py).testServer(116) - InvenTree server details: {"server": "InvenTree", "version": "0.6.0", "instance": "Inventree", "apiVersion": 26, "worker_running": true}
2022-04-12 22:55:18,671 - [INFO] - inventree - (api.py).requestToken(144) - Requesting auth token from server...
2022-04-12 22:55:18,672 - [DEBUG] - urllib3.connectionpool - (connectionpool.py)._new_conn(1001) - Starting new HTTPS connection (1): my.inventree.instance.tld:443
2022-04-12 22:55:19,285 - [DEBUG] - urllib3.connectionpool - (connectionpool.py)._make_request(456) - https://my.inventree.instance.tld:443 "GET /api/user/token/ HTTP/1.1" 200 52
2022-04-12 22:55:19,286 - [INFO] - inventree - (api.py).requestToken(168) - Authentication token: a_fancy_token_here
2022-04-12 22:55:19,286 - [DEBUG] - root - (mwe.py).<module>(25) - Requesting API at part/50/
2022-04-12 22:55:19,286 - [DEBUG] - inventree - (api.py).request(220) - Sending Request:
2022-04-12 22:55:19,294 - [DEBUG] - inventree - (api.py).request(224) -  - headers:
2022-04-12 22:55:19,299 - [DEBUG] - urllib3.connectionpool - (connectionpool.py)._new_conn(1001) - Starting new HTTPS connection (1): my.inventree.instance.tld:443
2022-04-12 22:55:19,504 - [DEBUG] - urllib3.connectionpool - (connectionpool.py)._make_request(456) - https://my.inventree.instance.tld:443 "GET /api/part/50/ HTTP/1.1" 200 1154
2022-04-12 22:55:19,505 - [INFO] - inventree - (api.py).request(246) - Request: GET https://my.inventree.instance.tld/api/part/50/ - 200
2022-04-12 22:55:19,505 - [DEBUG] - root - (mwe.py).<module>(27) - Done!

As well as the following console output:

--- Logging error ---
Traceback (most recent call last):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 196, in shouldRollover
    msg = "%s\n" % self.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 943, in format
    return fmt.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 678, in format
    record.message = record.getMessage()
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 368, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "d:\etc\py-kitree\mwe.py", line 26, in <module>
    result = Api.get(query)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 416, in get
    response = self.request(url, method='get', **kwargs)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 221, in request
    logger.debug(" - URL:", method, api_url)
Message: ' - URL:'
Arguments: ('GET', 'https://my.inventree.instance.tld/api/part/50/')
--- Logging error ---
Traceback (most recent call last):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 196, in shouldRollover
    msg = "%s\n" % self.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 943, in format
    return fmt.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 678, in format
    record.message = record.getMessage()
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 368, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "d:\etc\py-kitree\mwe.py", line 26, in <module>
    result = Api.get(query)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 416, in get
    response = self.request(url, method='get', **kwargs)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 222, in request
    logger.debug(" - auth:", auth)
Message: ' - auth:'
Arguments: (None,)
--- Logging error ---
Traceback (most recent call last):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 196, in shouldRollover
    msg = "%s\n" % self.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 943, in format
    return fmt.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 678, in format
    record.message = record.getMessage()
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 368, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "d:\etc\py-kitree\mwe.py", line 26, in <module>
    result = Api.get(query)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 416, in get
    response = self.request(url, method='get', **kwargs)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 223, in request
    logger.debug(" - params:", params)
Message: ' - params:'
Arguments: ({},)
--- Logging error ---
Traceback (most recent call last):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 196, in shouldRollover
    msg = "%s\n" % self.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 943, in format
    return fmt.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 678, in format
    record.message = record.getMessage()
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 368, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "d:\etc\py-kitree\mwe.py", line 26, in <module>
    result = Api.get(query)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 416, in get
    response = self.request(url, method='get', **kwargs)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 225, in request
    logger.debug(" - json:", json)
Message: ' - json:'
Arguments: ({},)
--- Logging error ---
Traceback (most recent call last):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 73, in emit
    if self.shouldRollover(record):
  File "D:\bin\python\3.10.4\lib\logging\handlers.py", line 196, in shouldRollover
    msg = "%s\n" % self.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 943, in format
    return fmt.format(record)
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 678, in format
    record.message = record.getMessage()
  File "D:\bin\python\3.10.4\lib\logging\__init__.py", line 368, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "d:\etc\py-kitree\mwe.py", line 26, in <module>
    result = Api.get(query)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 416, in get
    response = self.request(url, method='get', **kwargs)
  File "D:\bin\python\3.10.4\lib\site-packages\inventree\api.py", line 226, in request
    logger.debug(" - files:", files)
Message: ' - files:'
Arguments: ({},)

Workaround

The errors in this particular example seem to originate from inventree/api.py in line 220:

# inventree/api.py - line 220
logger.debug("Sending Request:")
logger.debug(" - URL:", method, api_url)
logger.debug(" - auth:", auth)
logger.debug(" - params:", params)
logger.debug(" - headers:", headers)
logger.debug(" - json:", json)
logger.debug(" - files:", files)

The debug method of the logging module is called with the variables to be logged as keyword arguments. The documentation of the debug method says:

debug(msg, *args, **kwargs):

The msg is the message format string, and the args are the arguments which are merged into msg using the string formatting operator.

The supplied string in the first argument of the function call does not contain any format placeholders for the formatting operator to merge the arguments into. It seems that this interfers with the logging module in some way when rotating file handlers are used. When changing these lines with the respective string placeholders like below, the MWE from above runs without errors:

# inventree/api.py - line 220
logger.debug("Sending Request:")
logger.debug(" - URL: %s %s", method, api_url)
logger.debug(" - auth: %s", auth)
logger.debug(" - params: %s", params)
logger.debug(" - headers: %s", headers)
logger.debug(" - json: %s", json)
logger.debug(" - files: %s", files)

Or better, Python f-strings could also be used here:

# inventree/api.py - line 220
logger.debug("Sending Request:")
logger.debug(f" - URL: {method} {api_url}")
logger.debug(f" - auth: {auth}", )
logger.debug(f" - params: {params}")
logger.debug(f" - headers: {headers}")
logger.debug(f" - json: {json}")
logger.debug(f" - files: {files}")

I would suggest using one of the two styles above when formatting logging messages in the API module, either the first one for backwards compatibility or the last one to comply with Python 3.6 specification. Let me know if this would be a correct fix for this problem and i will happily provide a pull request.

inventree / inventree-python