Перейти к основному содержимому

Шаг 10. Работа с журналом

Журнал - это текстовая запись с отметкой времени, структурированная (рекомендуется) или неструктурированная, с метаданными. Из всех телеметрических сигналов журналы имеют самое большое наследие. Большинство языков программирования имеют встроенные возможности ведения журнала или хорошо известные, широко используемые библиотеки ведения журнала. Хотя журналы являются независимым источником данных, они также могут быть присоединены к span-ам. В OpenTelemetry любые данные, которые не являются частью распределенной трассировки или метрики, являются журналом. Например, события - это особый тип журнала. Журналы часто содержат подробную отладочную/диагностическую информацию, например, входные данные для операции, результат операции и любые вспомогательные метаданные для этой операции.

Если приступить к изучению SDK для Python, то с удивлением можете для себя обнаружить, что в отличии от трассировок и метрик, не существует эквивалентного Logs API. Есть только SDK. Идея заключается в том, что вы можете использовать любой регистратор, который вы хотите для своего языка (в Python это библиотека logging), а затем отельный SDK подключает обработчик OTLP к корневому регистратору, по сути, превращая журналы вашей библиотеки журналов в журналы OTLP.

Звучит странно? Давайте разбираться.

Воспользуемся еще одной библиотекой OpenTelemetry Logging Instrumentation. Установить её можно с помощью команды:

pip install opentelemetry-instrumentation-logging

В app/requirements.txt:

Flask==3.0.0
opentelemetry-sdk==1.21.0
opentelemetry-exporter-prometheus==1.12.0rc1
opentelemetry-exporter-otlp-proto-grpc==1.21.0
opentelemetry-instrumentation==0.42b0
opentelemetry-instrumentation-flask==0.42b0
opentelemetry-instrumentation-logging==0.42b0

В app/app.py произведем следующие изменения:

import os
import logging
from logging.config import dictConfig

from typing import Iterable
from prometheus_client import generate_latest
from flask import Flask
from random import randint


from opentelemetry import trace, metrics
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.metrics import Observation, CallbackOptions
from opentelemetry.sdk.metrics import MeterProvider
from opentelemetry.exporter.prometheus import PrometheusMetricReader
from opentelemetry.instrumentation.flask import FlaskInstrumentor
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.sdk.resources import SERVICE_NAME, Resource


app = Flask(__name__)


def do_roll():
    with tracer.start_as_current_span("do_roll"):
        res = randint(1, 7)
        current_span = trace.get_current_span()
        current_span.set_attribute("roll.value", res)
        current_span.add_event("This is a span event")
        return res


def do_important_job():
    with tracer.start_as_current_span("do_important_job"):
        randint(1, 10000)


@app.route("/rolldice")
def roll_dice():
    request_counter.add(1)
    result = do_roll()
    do_important_job()
    if (result < 0 or result > 6):
        logging.getLogger().error("An incorrect number was received on the dice!")
        return 'something went wrong!', 500
    return str(result)


@app.route('/metrics')
def get_metrics():
    return generate_latest()


def cpu_time_callback(options: CallbackOptions) -> Iterable[Observation]:
    observations = []
    with open("/proc/stat") as procstat:
        procstat.readline()  # skip the first line
        for line in procstat:
            if not line.startswith("cpu"):
                break
            cpu, *states = line.split()
            observations.append(Observation(
                int(states[0]) // 100, {"cpu": cpu, "state": "user"}))
            observations.append(Observation(
                int(states[1]) // 100, {"cpu": cpu, "state": "system"}))
    return observations


def init_traces(resource):
    tracer_provider = TracerProvider(resource=resource)
    processor = BatchSpanProcessor(OTLPSpanExporter(
        endpoint=os.environ.get('TRACE_ENDPOINT', "http://localhost:4317")))
    tracer_provider.add_span_processor(processor)
    trace.set_tracer_provider(tracer_provider)
    tracer = trace.get_tracer(__name__)
    return tracer


def init_metrics(resource):
    metric_reader = PrometheusMetricReader()
    meter_provider = MeterProvider(
        resource=resource, metric_readers=[metric_reader])
    metrics.set_meter_provider(meter_provider)

    meter = metrics.get_meter_provider().get_meter(__name__)
    request_counter = meter.create_counter(
        name="request_counter", description="Number of requests", unit="1")
    meter.create_observable_counter(
        "system.cpu.time",
        callbacks=[cpu_time_callback],
        unit="s",
        description="CPU time"
    )
    return request_counter


def init_logs():
    LoggingInstrumentor().instrument(set_logging_format=True)
    dictConfig({
        'version': 1,
        'formatters': {'default': {
            'format': '%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s trace_sampled=%(otelTraceSampled)s] - %(message)s',
        }},
        'handlers': {'wsgi': {
            'class': 'logging.StreamHandler',
            'stream': 'ext://flask.logging.wsgi_errors_stream',
            'formatter': 'default'
        }},
        'root': {
            'level': 'INFO',
            'handlers': ['wsgi']
        }
    })


resource = Resource.create({SERVICE_NAME: os.environ.get(
    'APP_SERVICE_NAME', "my-python-service")})
tracer = init_traces(resource)
request_counter = init_metrics(resource)
init_logs()

FlaskInstrumentor().instrument_app(app)

if __name__ == "__main__":
    host = os.environ.get('APP_HOST_NAME', "0.0.0.0")
    port = int(os.environ.get('APP_PORT', 5000))
    app.run(host=host, port=port)

Какие изменения произошли:

  1. Добавлено событие трассировки в методе do_roll.
  2. Мы воспользовались стандартным средством журналирования Flask.
  3. Особое внимание обратите на свойство formatters в объекте аргумента метода dictConfig. Мы используем ключи otelSpanID, otelTraceID, otelServiceName, otelTraceSampled, которые используются в пользовательской фабрике инструментария ведения журнала OpenTelemetry. Но в коде определения этой фабрики вы не найдете. Давайте разберемся в этой магии поподробнее.
  4. Для того, чтобы мы могли форматированный вывод обеспечить, нам нужно инициализировать LoggingInstrumentor с аргументом set_logging_format равным true.

Нам также необходимо выполнить изменения в docker-compose.yaml:

services:
  app:
    image: iu5devops/app
    build:
      context: ./app
      dockerfile: Dockerfile
    container_name: iu5devops-app
    networks:
      - iu5devops
    ports:
      - 8080:5000
    environment:
      - FLASK_DEBUG=1
      - APP_SERVICE_NAME=iu5devops-app
      - TRACE_ENDPOINT=http://iu5devops-jaeger:4317
      - OTEL_PYTHON_LOG_CORRELATION=true
      - OTEL_PYTHON_LOG_LEVEL=info

  jaeger:
    image: jaegertracing/all-in-one
    container_name: iu5devops-jaeger
    networks:
      - iu5devops
    ports:
      - 16686:16686

  prometheus:
    image: prom/prometheus
    container_name: iu5devops-prometheus
    networks:
      - iu5devops
    ports:
      - 9090:9090
    volumes:
      - ./prometheus/prometheus.yml:/etc/prometheus/prometheus.yml
      - prometheus-data:/prometheus

  grafana:
    image: grafana/grafana
    container_name: iu5devops-grafana
    networks:
      - iu5devops
    ports:
      - 4000:3000
    volumes:
      - grafana-storage:/var/lib/grafana

volumes:
  grafana-storage: {}
  prometheus-data: {}

networks:
  iu5devops: {}

Важной переменной окружения является OTEL_PYTHON_LOG_CORRELATION со значением true. Она отвечает за интеграцию контекста трассировки в журналирование. Это важно потому что, если интеграция не включена, переменные контекста трассировки не вводятся в объекты записи журнала. Это означает, что любые попытки выполнения инструкций журнала, выполненных после установки формата ведения журнала и до включения этой интеграции, приведут к исключениям KeyError. Такие исключения автоматически проглатываются модулем ведения журнала и не приводят к сбоям, но вы все равно можете потерять важные сообщения журнала.

к сведению

Интеграция всегда регистрирует пользовательскую фабрику, которая вводит контекст трассировки в объекты записей журнала.

Переменную OTEL_PYTHON_LOG_LEVEL можно использовать для установки пользовательского уровня ведения журнала.

Соберите контейнер снова и запустите полученную конфигурацию:

docker compose down
docker compose build
docker compose up -d

Давайте посмотрим то, что получилось Jaeger:

  • В трассировке теперь отображаются события.

Jaeger события

Но в трассировке мы не видим событий, которые создаются средством журналирования logging.

В дело вступает Loki!