HTTP-запрос Python и ведение журнала уровня отладки в файле журнала - PullRequest
Новая
       3

HTTP-запрос Python и ведение журнала уровня отладки в файле журнала

1 голос
/ 06 ноября 2019

Мне трудно получить журналы уровня DEBUG в файле журнала для HTTP-запроса, например, с консоли, например: 

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

1 Ответ

3 голосов
/ 08 ноября 2019

Вы добавляете свои обработчики и изменения уровня не в том месте.

Модуль ведения журнала Python обрабатывает объекты средства ведения журнала как существующие в иерархии, основываясь на их имени и наличии разделителей . в этих именах. ,Имя "foo.bar.baz" для логгера логически помещается как дочерний элемент foo.bar и foo, если они существуют. В основе иерархии лежит корневой логгер, который не имеет имени. Вы получаете к нему доступ с помощью logging.getLogger() (без аргументов, хотя '' и None также будут работать).

Теперь при регистрации сообщений сначала сообщение должно пройти эффективный уровень * 1013. * регистратора. Если они передали, что сообщения передаются обработчикам на каждом регистраторе от текущего регистратора до корня, при условии, что они очищают уровень каждого найденного обработчика.

Чтобы найти эффективный уровень, иерархия обходит, чтобы найти ближайший объект регистратора с установленным уровнем;если их нет, то сообщения всегда проходят. При обходе иерархии для поиска обработчиков объект журнала может блокировать распространение (propagate установлено на False), и в этот момент обход останавливается.

Когда вы пытаетесь обработать сообщения для urllib3.connectionpool(),вам нужно поместить обработчик в одно из трех мест: регистратор для urllib3.connectionpool, для urllib3 или корневой регистратор. Ваш код этого не делает .

Вместо этого вы настраиваете свои обработчики на свой собственный регистратор с другим именем: 

_logger = logging.getLogger(__name__)

Это гарантированно не совпадаетКорневой регистратор (__name__ должен быть пустым, что никогда не бывает), ни urllib3 или urllib3.connectionpool регистраторы (что означает, что ваш модуль также называется urllib3 или urllib3.connectionpool).

* 1036. * Поскольку это не тот путь, по которому следуют urllib3.connectionpool сообщения журнала, ваши обработчики никогда не получат эти сообщения.

Вместо этого вы хотите настроить 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)

Вы можете просто установить уровень журнала каждого обработчика на уровень журнала, который вы хотите видеть в этом обработчике, а не в корневом регистраторе (или в дополнение к корневому). logger.) Помните, что уровень, установленный в корневом логгере, используется для определения эффективного уровня других логгеров в иерархии, для которых уровень не установлен напрямую, и что эффективный уровень работает как «верхняя отметка» для всех сообщений. . Если рут естьgger установлен на 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() 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

с примененным выше трюком 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> с уровнем, который вообще не установлен.

Добро пожаловать на сайт PullRequest, где вы можете задавать вопросы и получать ответы от других членов сообщества.

Нет похожих вопросов

...