Python HTTP 请求和调试级别记录到日志文件

Question

我很难在 HTTP 请求的日志文件中获取 DEBUG 级别日志，例如来自控制台的请求，例如:

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

对于下面的代码:

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)

当我用 logging.DEBUG 调用它时日志文件将只包含我将在代码中指定为 _logger.info 的任何内容或 _logger.debug与控制台日志输出没有什么相似之处。

PS。
示例代码如何调用它:

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

Answer 1

您在错误的位置添加处理程序和级别更改。

Python 日志记录模块将记录器对象视为存在于层次结构中，基于它们的名称和 . 的存在。这些名称中的分隔符。姓名"foo.bar.baz"对于记录器，逻辑上放置为 foo.bar 的子级和 foo ，它们是否存在。层次结构的基础是根记录器，它没有名称。您可以通过 logging.getLogger() 访问它(没有参数，虽然 '' 和 None 也可以工作)。

现在，在记录消息时，首先消息必须通过记录器的有效级别。如果他们通过了，则消息将传递给从当前记录器到根的每个记录器上的处理程序，前提是他们清除找到的每个处理程序的级别。

为了找到有效级别，遍历层次结构以找到最近的具有级别集的记录器对象；如果没有，则消息总是通过。在遍历层次结构以查找处理程序时，日志对象可以阻止传播( propagate 设置为 False )，此时遍历停止。

当您尝试处理 urllib3.connectionpool() 的消息时，您需要将处理程序放在三个位置之一:urllib3.connectionpool 的记录器, 对于 urllib3或根记录器。你的代码没有这样做。

相反，您可以在自己的记录器上使用不同的名称设置处理程序:

_logger = logging.getLogger(__name__)

这保证不匹配根记录器( __name__ 需要为空，绝不是这种情况)也不匹配 urllib3或 urllib3.connectionpool记录器(这意味着您的模块也称为 urllib3 或 urllib3.connectionpool) 。

因为它不在 urllib3.connectionpool的路径中日志消息将随之而来，您的处理程序将永远不会收到这些消息。

相反，您要配置根记录器:

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)

您可以将每个处理程序的日志级别设置为您希望在该处理程序上看到的日志级别，而不是在根记录器上(或除了根记录器之外)。请记住，根记录器上设置的级别用于确定层次结构中没有直接设置级别的其他记录器的有效级别，并且有效级别用作所有消息的“高水位标记”。如果根记录器设置为 INFO ，并且没有配置其他处理程序，那么您的处理程序将永远不会看到 DEBUG消息。根记录器的默认级别是 WARNING .

您通常只想在模块中使用命名记录器来生成日志消息，并将所有处理程序放在根目录上。其他任何东西都是专门的，“高级”使用记录器模块(例如，一个专用的、单独的处理程序只用于 urllib3 日志消息，或者通过将其最低级别的记录器对象设置为 propagate = False 来使整个包静音)。

最后， logging.basicConfig()也配置根记录器，但前提是根记录器上已经没有处理程序。如果您使用 force=True然后 basicConfig()将删除所有现有的处理程序，然后在根上配置处理程序。它总是会创建一个 Formatter()实例并将其设置在所有处理程序上。

您可以使用 basicConfig()满足您的所有根记录器需求:

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
    )

旁注: http.client图书馆 不使用 logging 输出调试信息；它将始终使用 print()输出那些。如果您想看到这些消息出现在您的日志中，您需要对库进行猴子补丁，添加替代 print()全局的:

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

以上 http.client应用技巧和 setup_logging(logging.DEBUG) ，我看到以下日志都出现在 stdout当我使用 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

您可以使用以下文件重现此内容:

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

除了上面的代码之外还添加了。然后您可以使用 python <script.py> -v将级别设置为详细并将其与 python <script.py> 进行比较根本没有设置级别。