Python HTTP request and debug level logging to the log file

Question

I have a hard time to get DEBUG level logs in a log file for HTTP request like those from console like:

DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): URI:443
DEBUG:urllib3.connectionpool:URL:443 "POST /endpoint HTTP/1.1" 200 None

for the code below:

import logging
from logging.handlers import TimedRotatingFileHandler
_logger = logging.getLogger(__name__)

    def setup_logging(loglevel):
        logFormatter = logging.Formatter("%(asctime)s [%(threadName)-12.12s] [%(levelname)-5.5s]  %(message)s")

        if loglevel is not None:
            if loglevel == 10:
                  http.client.HTTPConnection.debuglevel = 1
            logformat = "%(asctime)s [%(threadName)-12.12s] [%(levelname)-5.5s]  %(message)s"
            logging.basicConfig(level=loglevel, stream=sys.stdout, format=logformat, datefmt="%Y-%m-%d %H:%M:%S")

        fileHandler = logging.handlers.TimedRotatingFileHandler("{0}/{1}.log".format(logPath, logFileName), when="midnight")
        fileHandler.setFormatter(logFormatter)
        _logger.setLevel(logging.DEBUG)
        _logger.addHandler(fileHandler)

When I will call it with logging.DEBUG log file will only contains whatever I will specify in the code as _logger.info or _logger.debug nothing similar like for the console log output.

PS. Example code how do I call it:

def main(args):
    args = parse_args(args)
    cfg = config(args.env)
    setup_logging(logging.DEBUG, cfg)
    requests.get("https://stackoverflow.com/a/58769712/100297")

There is nothing special about the console logger. Are you certain that you haven't already called `basicConfig` before? — Martijn Pieters, Nov 07 '19 at 17:08
What is `_logger` here? Could you please add a small test script that reproduces the issue? Perhaps use `"-d" in sys.argv` as a test to switch between log levels, and that uses `requests` to make a request to something. — Martijn Pieters, Nov 07 '19 at 17:11
@MartijnPieters I have updated OP. Regarding adding arguments I have added in my initial issue described here https://stackoverflow.com/q/58735405/1090360 which the outcome is current problem. `basicConfig` is called only in case of the verbose request. Log files should be created all the time. — JackTheKnife, Nov 07 '19 at 18:10
Your code only sets the current logger to level debug; basicConfig sets the root logger level. Urllib3 is not logging through your local logger object, it goes to the root and handlers there. — Martijn Pieters, Nov 08 '19 at 03:54
@MartijnPieters so do I need to have two loggers then - one for the stdout and one for the log files? — JackTheKnife, Nov 08 '19 at 14:57
No, but you are currently configuring two different things here. — Martijn Pieters, Nov 08 '19 at 15:09
@MartijnPieters OK, so how can I set logger which will log to the file as `logging.DEBUG` and will log same data as stdout does when run as verbose? — JackTheKnife, Nov 08 '19 at 15:27

Martijn Pieters · Accepted Answer · 2019-11-08T16:32:05.130

You are adding your handlers and level changes in the wrong place.

The Python logging module treats logger objects as existing in a hierarchy, based on their name and the presence of . delimiters in those names. The name "foo.bar.baz" for a logger is logically placed as child of foo.bar and of foo, should they exist. At the base of the hierarchy is the root logger, which has no name. You access it with logging.getLogger() (no arguments, although '' and None also would work).

Now, when logging messages, first the message has to pass the effective level of the logger. If they passed that the messages are passed to the handlers on every logger from the current logger down to the root, provided they clear the level of each handler found.

To find the effective level, the hierarchy is traversed to find the nearest logger object with a level set; if there are none then messages always pass. When traversing the hierarchy to find handlers, a log object can block propagation (propagate is set to False), at which point traversing stops.

When you are trying to handle messages for urllib3.connectionpool(), you need to put a handler on one of three locations: the logger for urllib3.connectionpool, for urllib3 or the root logger. Your code doesn't do that.

You instead set up your handlers on your own logger with a different name:

_logger = logging.getLogger(__name__)

That is guaranteed to not match the root logger (__name__ would need to be empty, that's never the case) nor the urllib3 or urllib3.connectionpool loggers (which would mean your module is also called urllib3 or urllib3.connectionpool).

Because it is not in the path that urllib3.connectionpool log messages would follow, your handlers are never going to be given those messages.

Instead, you want to configure the root logger:

fileHandler = logging.handlers.TimedRotatingFileHandler("{0}/{1}.log".format(logPath, logFileName), when="midnight")
fileHandler.setFormatter(logFormatter)
root = logging.getLogger()
root.setLevel(logging.DEBUG)
root.addHandler(fileHandler)

You could just set the log level of each handler to a log level you want to see on that handler, rather than on the root logger (or in addition to the root logger). Remember that the level set on the root logger is used to determine the effective level of other loggers in the hierarchy that don't have a level set directly and that the effective level works as a 'high water mark' for all messages. If the root logger is set to INFO, and no other handlers are configured, then your handlers will never see DEBUG messages. The default level for the root logger is WARNING.

You usually only ever want to use named loggers in your modules to produce log messages, and put all your handlers on the root. Anything else is specialised, 'advanced' use of the logger module (e.g. a dedicated, separate handler just for the urllib3 log messages, or silencing a whole package by setting their lowest-level logger object to propagate = False).

Finally, logging.basicConfig() configures the root logger too, but only if there are no handlers on the root logger already. If you use force=True then basicConfig() will remove all existing handlers, then configure the handlers on the root. It'll always create a Formatter() instance and set it on all handlers.

You could use basicConfig() for all your root logger needs:

import http.client
import logging
import os.path
import sys
from logging.handlers import TimedRotatingFileHandler

def setup_logging(loglevel):
    # the file handler receives all messages from level DEBUG on up, regardless
    fileHandler = TimedRotatingFileHandler(
        os.path.join(logPath, logFileName + ".log"),
        when="midnight"
    )
    fileHandler.setLevel(logging.DEBUG)
    handlers = [fileHandler]

    if loglevel is not None:
        # if a log level is configured, use that for logging to the console
        stream_handler = logging.StreamHandler(sys.stdout)
        stream_handler.setLevel(loglevel)
        handlers.append(stream_handler)

    if loglevel == logging.DEBUG:
        # when logging at debug level, make http.client extra chatty too
        # http.client *uses `print()` calls*, not logging.
        http.client.HTTPConnection.debuglevel = 1

    # finally, configure the root logger with our choice of handlers
    # the logging level of the root set to DEBUG (defaults to WARNING otherwise).
    logformat = "%(asctime)s [%(threadName)-12.12s] [%(levelname)-5.5s]  %(message)s"
    logging.basicConfig(
        format=logformat, datefmt="%Y-%m-%d %H:%M:%S",
        handlers=handlers, level=logging.DEBUG
    )

Side note: the http.client library does not use logging to output debug messages; it will always use print() to output those. If you want to see those messages appear in your logs, you'll need to monkey-patch the library, adding in an alternative print() global:

import http.client
import logging

http_client_logger = logging.getLogger("http.client")

def print_to_log(*args):
    http_client_logger.debug(" ".join(args)) 

# monkey-patch a `print` global into the http.client module; all calls to
# print() in that module will then use our print_to_log implementation
http.client.print = print_to_log

With the above http.client trick applied and setup_logging(logging.DEBUG), I see the following logs appear both on stdout and in the file when I use requests.get("https://stackoverflow.com/a/58769712/100297"):

2019-11-08 16:17:26 [MainThread  ] [DEBUG]  Starting new HTTPS connection (1): stackoverflow.com:443
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  send: b'GET /a/58769712/100297 HTTP/1.1\r\nHost: stackoverflow.com\r\nUser-Agent: python-requests/2.22.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  reply: 'HTTP/1.1 302 Found\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Cache-Control: private
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Type: text/html; charset=utf-8
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Location: /questions/58738195/python-http-request-and-debug-level-logging-to-the-log-file/58769712#58769712
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Frame-Options: SAMEORIGIN
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Request-Guid: 761bd2f8-3e5c-453a-ab46-d01284940541
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Strict-Transport-Security: max-age=15552000
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Feature-Policy: microphone 'none'; speaker 'none'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Security-Policy: upgrade-insecure-requests; frame-ancestors 'self' https://stackexchange.com
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Length: 214
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Date: Fri, 08 Nov 2019 16:17:27 GMT
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Via: 1.1 varnish
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Connection: keep-alive
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Served-By: cache-lhr7324-LHR
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache: MISS
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache-Hits: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Timer: S1573229847.069848,VS0,VE80
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Vary: Fastly-SSL
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-DNS-Prefetch-Control: off
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Set-Cookie: prov=0e92634f-abce-9f8e-1865-0d35ebecc595; domain=.stackoverflow.com; expires=Fri, 01-Jan-2055 00:00:00 GMT; path=/; HttpOnly
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  https://stackoverflow.com:443 "GET /a/58769712/100297 HTTP/1.1" 302 214
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  send: b'GET /questions/58738195/python-http-request-and-debug-level-logging-to-the-log-file/58769712 HTTP/1.1\r\nHost: stackoverflow.com\r\nUser-Agent: python-requests/2.22.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nCookie: prov=0e92634f-abce-9f8e-1865-0d35ebecc595\r\n\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  reply: 'HTTP/1.1 200 OK\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Cache-Control: private
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Type: text/html; charset=utf-8
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Encoding: gzip
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Last-Modified: Fri, 08 Nov 2019 16:16:07 GMT
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Frame-Options: SAMEORIGIN
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Request-Guid: 5e48399e-a91c-44aa-aad6-00a96014131f
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Strict-Transport-Security: max-age=15552000
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Feature-Policy: microphone 'none'; speaker 'none'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Security-Policy: upgrade-insecure-requests; frame-ancestors 'self' https://stackexchange.com
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Length: 42625
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Date: Fri, 08 Nov 2019 16:17:27 GMT
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Via: 1.1 varnish
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Connection: keep-alive
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Served-By: cache-lhr7324-LHR
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache: MISS
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache-Hits: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Timer: S1573229847.189349,VS0,VE95
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Vary: Accept-Encoding,Fastly-SSL
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-DNS-Prefetch-Control: off
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  https://stackoverflow.com:443 "GET /questions/58738195/python-http-request-and-debug-level-logging-to-the-log-file/58769712 HTTP/1.1" 200 42625

You can reproduce this with a file with:

import requests
import sys

logPath, logFileName = "/tmp", "demo"
level = logging.DEBUG if "-v" in sys.argv else None
setup_logging(level)

requests.get("https://stackoverflow.com/a/58769712/100297")

added in addition to the code above. You can then use python <script.py> -v to set the level to verbose and compare that to python <script.py> with the level not set at all.

And what happened to the `_logger = logging.getLogger()` in the case above? How should I call `_logger` in that case? — JackTheKnife, Nov 08 '19 at 15:58
@JackTheKnife: you are free to use your own logger still, just don't put handlers on it. If you have other code that calls `_logger.log()` or any of the level-specific methods, then that's fine. You just wouldn't use it in `setup_logging()`. — Martijn Pieters, Nov 08 '19 at 15:59
That is the case to use `setup_logging()` to have verbose to the console based on passed there level when log to file will keep it going on the DEBUG level. I have tried to use your solution but no logs were produced from it to the console or file. — JackTheKnife, Nov 08 '19 at 16:05
@JackTheKnife: yes, the file handler is specifically configured to use level DEBUG. I tried this out just now, it works as exactly as expected. — Martijn Pieters, Nov 08 '19 at 16:09
@JackTheKnife: are you certain `basicConfig()` wasn't already called? You can add `force=True` to the `basicConfig()` call to have it remove all previous handlers and force setting your own. — Martijn Pieters, Nov 08 '19 at 16:12
I have only one `basicConfig` in the `setup_logging()` then for testing purposes I have added `setup_logging(logging.DEBUG) logger = logging.getLogger() logger.info("INFO test") logger.debug("DEBUG test")` in the `main()` — JackTheKnife, Nov 08 '19 at 16:16
@JackTheKnife: without seeing how you call this (as a proper mcve that reproduces the issue) I can't help you, I'm sorry. The code in my answer, when adding to a file and then with `setup_logging(logging.DEBUG)` and `requests.get("....")` produces the output I show in my answer, both on the console and in the log file. — Martijn Pieters, Nov 08 '19 at 16:21
@JackTheKnife: ahA! Sorry, I have my root logger default altered. It defaults to WARNING. I'll update, have `basicConfig` use `level=logging.DEBUG`. — Martijn Pieters, Nov 08 '19 at 16:30
Let us [continue this discussion in chat](https://chat.stackoverflow.com/rooms/202065/discussion-between-jacktheknife-and-martijn-pieters). — JackTheKnife, Nov 08 '19 at 16:34
For those using python3.4, the correct signature for the `print_to_log` function above is `print_to_log(*args, **kwargs)`. — Simon Righley, Nov 25 '19 at 12:47

score 1 · Answer 2 · answered Jun 06 '22 at 03:24

Here's a simple solution for underlying urllib3:

https://urllib3.readthedocs.io/en/stable/user-guide.html#logging

Example:

logging.getLogger("urllib3").setLevel(logging.WARNING)

Sample output:

>>> requests.get('http://www.google.com')
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): www.google.com:80
DEBUG:urllib3.connectionpool:http://www.google.com:80 "GET / HTTP/1.1" 200 6073
<Response [200]>

If you need it redirected to a file as well, use

>>> file_handler = logging.FileHandler('log.txt')
>>> logging.getLogger('urllib3').addHandler(file_handler)
>>> requests.get('http://www.google.com')

Sample output in log.txt:

$ cat log.txt
Starting new HTTP connection (1): www.google.com:80
http://www.google.com:80 "GET / HTTP/1.1" 200 6129

If you need a sophisticated formatting, use a custom formatter. https://docs.python.org/3.9/library/logging.html#formatter-objects

Python HTTP request and debug level logging to the log file

2 Answers2

Linked