Custom python logging handler looping continuously

Question

I'm running into some sort of looping issue attempting to implement logging in my project using a custom handler so I'm seeking for help. I do have some programming experience but I'm pretty new to python so maybe I get this all wrong.

As shown below, I get a "RecursionError". I've also attached a truncated copy of the error as well as the code at the end of this post.

Thanks in advance !

Error:

Traceback (most recent call last):
  File "app.py", line 18, in <module>
    logger.debug('debug message!')
  File "/usr/lib/python3.8/logging/__init__.py", line 1422, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib/python3.8/logging/__init__.py", line 1577, in _log
    self.handle(record)
  File "/usr/lib/python3.8/logging/__init__.py", line 1587, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.8/logging/__init__.py", line 1649, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.8/logging/__init__.py", line 950, in handle
    self.emit(record)
  File "/app/python/logger_handlers.py", line 27, in emit
    requests.post(self.url, headers = header, data = json.dumps(payload))
[...truncated...]
RecursionError: maximum recursion depth exceeded in comparison

# app.py
import logging
import my_module
from logger_handlers import CustomHandler

logging.getLogger("requests").disabled = True

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# Custom handler
custom_handler = CustomHandler(url = 'http://some_url.com/api/1/log')
custom_handler.setLevel(logging.DEBUG)
custom_handler.setFormatter(formatter)
logger.addHandler(custom_handler)

# Log to root handler
logger.debug('debug message!')

# Run a function in a different module that also has a logger defined 
my_module.run()

# my_module.py
import logging

log = logging.getLogger(__name__)
log.addHandler(logging.NullHandler())

def run():
    log.debug('A message from A Module')

# logger_handlers.py
import logging
import requests
import json

from socket import gethostname, gethostbyname

class CustomHandler(logging.Handler):

    def __init__(self, *args, **kwargs):
        super().__init__()
        self.url = kwargs['url']

    def emit(self, record):
        message = self.format(record)
        header = {"content-type": "application/json"}
        payload = {
            "token":None,
            "client_version":"",
            "parameters": {
                "source": "Host: {} ({}), Module: {}, {}".format(gethostname(), gethostbyname(gethostname()), record.filename, record.funcName),
                "severity": record.levelname,
                "message": message
            }
        }
        requests.post(self.url, headers = header, data = json.dumps(payload))

UPDATE (2020-04-03):

By using this snippet I was able to identify all the loggers I had to disable to avoid the loop:

for key in logging.Logger.manager.loggerDict:
    print(key)

I then use this to disable them:

logging.getLogger("urllib3.util.retry").disabled = True
logging.getLogger("urllib3.util").disabled = True
logging.getLogger("urllib3").disabled = True
logging.getLogger("urllib3.connection").disabled = True
logging.getLogger("urllib3.response").disabled = True
logging.getLogger("urllib3.connectionpool").disabled = True
logging.getLogger("urllib3.poolmanager").disabled = True
logging.getLogger("requests").disabled = True

Not super pretty but it works. Please feel free to comment if you think there's a major drawback to this method.

score 0 · Answer 1 · answered Mar 23 '20 at 15:03

0

In your app.py script, just pass name as the name parameter to getLogger(). So,

logger = logging.getLogger(__name__)

answered Mar 23 '20 at 15:03

ShlokSayani

91
3

Hmm... When I do this, only the logs in app.py shows up. The log.debug('A message from A Module') in the my_module.py does not get captured. – Robert Apr 01 '20 at 15:38

score 0 · Accepted Answer · answered Mar 23 '20 at 15:55

0

When doing a request with the requests module logs are created. Some from the requests logger but also some from other libraries that are used. The urllib module for example also has a logger that creates logs. These logs propagate up the log hierarchy and end up in the root logger. The root logger also has your handler, and thus will again do q request, creating more logs that end up at the root logger.

Only add your handler to loggers that requests logs don't propagate to.

answered Mar 23 '20 at 15:55

blues

4,547
3
23
39

Please excuse my ignorance but I'm really not sure I get it... Remember that the goal is to define a root logger in app.py so that it is possible to use the logging module in an external module like my_module.py so it can propagate to the root logger in app.py. Also, shouldn't this line disable log generation for the requests module: logging.getLogger("requests").disabled = True ? If you'd be kind enough to provide an example it would greatly help ? – Robert Apr 01 '20 at 15:58
The line you have only disables logging from the requests module itself. When using the requests module, other modules are also included and are generating logs, and those are not disabled. The `urllib` module still generates logs when doing a request. I very much recommend _not_ using the root logger for your case. just use any other named logger `logger = logging.getLogger('roberts_logger')` in app.py and `logger = logging.getLogger('roberts_logger.my_module')` in my_module.py. And add the handler(s) to `roberts_logger` – blues Apr 02 '20 at 06:30
Thanks for the extra info @blues. I think I have found a way to disable them all. Please look at my latest update above. – Robert Apr 03 '20 at 15:21

Custom python logging handler looping continuously

2 Answers2

Linked