Повторяющиеся записи в журнале с помощью Google Cloud Stackdriver регистрируют код Python в Kubernetes Engine

Question

У меня есть простое приложение Python, работающее в контейнере в Google Kubernetes Engine. Я пытаюсь подключить стандартное ведение журнала Python к ведению журнала Google Stackdriver, используя это руководство: https://cloud.google.com/logging/docs/setup/python. Я почти преуспел, но я получаю дубликаты записей журнала, один из которых всегда находится на уровне "ошибка"...

---

Снимок экрана: журналы Stackdriver с дублирующимися записями

Это мой код Python, который настраивает ведение журнала в соответствии с приведенным выше руководством:

import webapp2
from paste import httpserver
import rpc

# Imports the Google Cloud client library
import google.cloud.logging
# Instantiates a client
client = google.cloud.logging.Client()
# Connects the logger to the root logging handler; by default this captures
# all logs at INFO level and higher
client.setup_logging()

app = webapp2.WSGIApplication([('/rpc/([A-Za-z]+)', rpc.RpcHandler),], debug=True)
httpserver.serve(app, host='0.0.0.0', port='80')

Вот код, который запускает журналы со скриншота:

import logging

logging.info("INFO Entering PostEchoPost...")
logging.warning("WARNING Entering PostEchoPost...")
logging.error("ERROR Entering PostEchoPost...")
logging.critical("CRITICAL Entering PostEchoPost...")

Вот полный журнал Stackdriver, расширенный со скриншота, с неверно интерпретированным уровнем ERROR:

{
 insertId:  "1mk4fkaga4m63w1"  
 labels: {
  compute.googleapis.com/resource_name:  "gke-alg-microservice-default-pool-xxxxxxxxxx-ttnz"   
  container.googleapis.com/namespace_name:  "default"   
  container.googleapis.com/pod_name:  "esp-alg-xxxxxxxxxx-xj2p2"   
  container.googleapis.com/stream:  "stderr"   
 }
 logName:  "projects/projectname/logs/algorithm"  
 receiveTimestamp:  "2018-01-03T12:18:22.479058645Z"  
 resource: {
  labels: {
   cluster_name:  "alg-microservice"    
   container_name:  "alg"    
   instance_id:  "703849119xxxxxxxxxx"   
   namespace_id:  "default"    
   pod_id:  "esp-alg-xxxxxxxxxx-xj2p2"    
   project_id:  "projectname"    
   zone:  "europe-west1-b"    
  }
  type:  "container"   
 }
 severity:  "ERROR"  
 textPayload:  "INFO Entering PostEchoPost...
"  
 timestamp:  "2018-01-03T12:18:20Z"  
}

Вот полный журнал Stackdriver, расширенный со скриншота, с правильно интерпретированным уровнем INFO:

{
 insertId:  "1mk4fkaga4m63w0"  
 jsonPayload: {
  message:  "INFO Entering PostEchoPost..."   
  thread:  140348659595008   
 }
 labels: {
  compute.googleapis.com/resource_name:  "gke-alg-microservi-default-pool-xxxxxxxxxx-ttnz"   
  container.googleapis.com/namespace_name:  "default"   
  container.googleapis.com/pod_name:  "esp-alg-xxxxxxxxxx-xj2p2"   
  container.googleapis.com/stream:  "stderr"   
 }
 logName:  "projects/projectname/logs/algorithm"  
 receiveTimestamp:  "2018-01-03T12:18:22.479058645Z"  
 resource: {
  labels: {
   cluster_name:  "alg-microservice"    
   container_name:  "alg"    
   instance_id:  "703849119xxxxxxxxxx"    
   namespace_id:  "default"    
   pod_id:  "esp-alg-xxxxxxxxxx-xj2p2"    
   project_id:  "projectname"    
   zone:  "europe-west1-b"    
  }
  type:  "container"   
 }
 severity:  "INFO"  
 timestamp:  "2018-01-03T12:18:20.260099887Z"  
}

Таким образом, эта запись может быть ключом:

container.googleapis.com/stream:  "stderr" 

Похоже, что в дополнение к моей работе по настройке ведения журналов все журналы из контейнера отправляются на контейнер stderr в контейнере, и я считаю, что по умолчанию, по крайней мере в Kubernetes Container Engine, все stdout/stderr выбираются Google Stackdriver через FluentD... Сказав это, я сейчас не в себе.

Любые идеи, почему я получаю эти дубликаты записей?

Answer 1

Я решил эту проблему, перезаписав handlers свойство в моем корневом регистраторе сразу после вызова setup_logging метод

import logging
from google.cloud import logging as gcp_logging
from google.cloud.logging.handlers import CloudLoggingHandler, ContainerEngineHandler, AppEngineHandler

logging_client = gcp_logging.Client()
logging_client.setup_logging(log_level=logging.INFO)
root_logger = logging.getLogger()
# use the GCP handler ONLY in order to prevent logs from getting written to STDERR
root_logger.handlers = [handler
                        for handler in root_logger.handlers
                        if isinstance(handler, (CloudLoggingHandler, ContainerEngineHandler, AppEngineHandler))]

Чтобы уточнить это немного, client.setup_loggingметод устанавливает 2 обработчика, нормальныйlogging.StreamHandlerа также обработчик, специфичный для GCP. Таким образом, журналы будут отправляться как в стандартный поток, так и в Cloud Logging. Вам необходимо удалить обработчик потока из списка обработчиков, чтобы предотвратить дублирование.

РЕДАКТИРОВАТЬ: я подал в Google проблему, чтобы добавить аргумент, чтобы сделать это менее взломанным.

Answer 2

Написано в 2022 году, вскоре после выпуска версии 3.0.0, и эта проблема возникла и у меня (хотя почти наверняка по другой причине).

Отладка

Самое полезное, что я сделал на пути к отладке, это вставил в свой код следующее:

      import logging
...
root_logger = logging.getLogger()  # no arguments = return the root logger
print(root_logger.handlers, flush=True)  # tell me what handlers are attached
...

Если вы получаете дубликаты журналов, вполне вероятно, что это связано с тем, что к вашему регистратору подключено несколько обработчиков, и Stackdriver перехватывает журналы от обоих! Честно говоря, это работа Stackdriver; жаль только, что нельзя разобраться с этим по умолчанию.

Хорошая новость заключается в том, что Stackdriver также поймает printоператор (который переходит в поток STDOUT). В моем случае логировался следующий список обработчиков: [<StreamHandler <stderr> (NOTSET)>, <StructuredLogHandler <stderr> (NOTSET)>]. Итак: к корневому логгеру были прикреплены два обработчика.

Исправление

Возможно, вы обнаружите, что ваш код прикрепляет обработчик где-то еще, и просто удалите эту часть. Но вместо этого может быть так, что, например, зависимость устанавливает дополнительный обработчик, с чем я боролся.

Я использовал решение, основанное на ответе, написанном Энди Карлсоном . Сохранение общего/расширяемого:

      import google.cloud.logging
import logging

def is_cloud_handler(handler: logging.Handler) -> bool:
    """
    is_cloud_handler

    Returns True or False depending on whether the input is a
    google-cloud-logging handler class

    """
    accepted_handlers = (
        google.cloud.logging.handlers.StructuredLogHandler,
        google.cloud.logging.handlers.CloudLoggingHandler,
        google.cloud.logging.handlers.ContainerEngineHandler,
        google.cloud.logging.handlers.AppEngineHandler,
    )
    return isinstance(handler, accepted_handlers)


def set_up_logging():
    # here we assume you'll be using the basic logging methods
    # logging.info, logging.warn etc. which invoke the root logger
    client = google.cloud.logging.Client()
    client.setup_logging()

    root_logger = logging.getLogger()
    root_logger.handlers = [h for h in root_logger.handlers if is_cloud_handler(h)]

Больше контекста

Для тех, кто находит это решение запутанным

В Python существует разделение между «регистраторами» и «обработчиками»: регистраторы генерируют журналы, а обработчики решают, что с ними происходит. Таким образом, вы можете прикрепить несколько обработчиков к одному и тому же регистратору (на случай, если вы хотите, чтобы с журналами из этого регистратора происходило несколько событий).

Библиотека предлагает запустить ее setup_loggingметод, а затем просто используйте основные методы ведения журнала встроенного loggingбиблиотека для создания журналов. Это: logging.debug, , logging.warning, logging.error, а также logging.critical(в порядке возрастания срочности).

Все logging.Loggerэкземпляры имеют одни и те же методы, включая специальный экземпляр, называемый корневым регистратором. Если вы посмотрите исходный код основных методов ведения журнала , они просто вызывают эти методы на этом корневом регистраторе.

Можно настроить определенные s, что является стандартной практикой для разграничения журналов, созданных различными областями приложения (вместо того, чтобы отправлять все через корневой регистратор). Это делается с помощью logging.getLogger("name-of-logger"). Однако, logging.getLogger()без аргументов возвращает корневой регистратор.

Между тем, цель google.cloud.logging.Client.setup_loggingМетод заключается в присоединении специального обработчика журнала к корневому регистратору . Таким образом, журналы, созданные с использованием logging.infoи т. д. будут обрабатываться google-cloud-loggingобработчик. Но вы должны убедиться, что к корневому регистратору не подключены другие обработчики.

К счастью, Loggers иметь собственность, .handlers, который представляет собой список прикрепленных обработчиков журналов. В этом решении мы просто редактируем этот список, чтобы убедиться, что у нас есть только один обработчик.

Answer 3

Проблема в том, как клиент регистрации инициализирует корневой регистратор

    logger = logging.getLogger()
    logger.setLevel(log_level)
    logger.addHandler(handler)
    logger.addHandler(logging.StreamHandler())

он добавляет обработчик потока по умолчанию в дополнение к обработчику Stackdriver. На данный момент мое решение - инициализировать соответствующий обработчик Stackdriver вручную:

            # this basically manually sets logger compatible with GKE/fluentd
            # as LoggingClient automatically add another StreamHandler - so 
            # log records are duplicated
            from google.cloud.logging.handlers import ContainerEngineHandler
            formatter = logging.Formatter("%(message)s")
            handler = ContainerEngineHandler(stream=sys.stderr)
            handler.setFormatter(formatter)
            handler.setLevel(level)
            root = logging.getLogger()
            root.addHandler(handler)
            root.setLevel(level)