Логирование | Реалистичные приложения | Django

В этой статье мы настроим логирование приложения в Kubernetes и разберём его особенности, а также сделаем структурированный формат логов для последующего парсинга системами сбора и анализа логов.

Приложение в этой статье не предназначено для использования в production без доработки. Готовое к работе в production приложение мы получим в конце руководства.

Подготовка окружения

Если вы ещё не подготовили своё рабочее окружение на предыдущих этапах, сделайте это в соответствии с инструкциями статьи «Подготовка окружения».

Если ваше рабочее окружение работало, но перестало, или же последующие инструкции из этой статьи не работают — попробуйте следующее:

Работает ли Docker?

Linux macOS Windows

Запустим приложение Docker Desktop. Приложению понадобится некоторое время для того, чтобы запустить Docker. Если никаких ошибок в процессе запуска не возникло, то проверим, что Docker запущен и корректно настроен:

docker run hello-world

Результат успешного выполнения команды:

Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
b8dfde127a29: Pull complete
Digest: sha256:9f6ad537c5132bcce57f7a0a20e317228d382c3cd61edae14650eec68b2b345c
Status: Downloaded newer image for hello-world:latest

Hello from Docker!
This message shows that your installation appears to be working correctly.

При возникновении проблем обратитесь к документации Docker для их устранения.

docker run hello-world

Результат успешного выполнения команды:

Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
b8dfde127a29: Pull complete
Digest: sha256:9f6ad537c5132bcce57f7a0a20e317228d382c3cd61edae14650eec68b2b345c
Status: Downloaded newer image for hello-world:latest

Hello from Docker!
This message shows that your installation appears to be working correctly.

При возникновении проблем обратитесь к документации Docker для их устранения.

Запустим Docker:

sudo systemctl restart docker

Убедимся, что Docker запустился:

sudo systemctl status docker

Результат выполнения команды, если Docker успешно запущен:

● docker.service - Docker Application Container Engine
     Loaded: loaded (/lib/systemd/system/docker.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2021-06-24 13:05:17 MSK; 13s ago
TriggeredBy: ● docker.socket
       Docs: https://docs.docker.com
   Main PID: 2013888 (dockerd)
      Tasks: 36
     Memory: 100.3M
     CGroup: /system.slice/docker.service
             └─2013888 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock

dockerd[2013888]: time="2021-06-24T13:05:16.936197880+03:00" level=warning msg="Your kernel does not support CPU realtime scheduler"
dockerd[2013888]: time="2021-06-24T13:05:16.936219851+03:00" level=warning msg="Your kernel does not support cgroup blkio weight"
dockerd[2013888]: time="2021-06-24T13:05:16.936224976+03:00" level=warning msg="Your kernel does not support cgroup blkio weight_device"
dockerd[2013888]: time="2021-06-24T13:05:16.936311001+03:00" level=info msg="Loading containers: start."
dockerd[2013888]: time="2021-06-24T13:05:17.119938367+03:00" level=info msg="Loading containers: done."
dockerd[2013888]: time="2021-06-24T13:05:17.134054120+03:00" level=info msg="Daemon has completed initialization"
systemd[1]: Started Docker Application Container Engine.
dockerd[2013888]: time="2021-06-24T13:05:17.148493957+03:00" level=info msg="API listen on /run/docker.sock"

Теперь проверим, что Docker доступен и корректно настроен:

docker run hello-world

Результат успешного выполнения команды:

Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
b8dfde127a29: Pull complete
Digest: sha256:9f6ad537c5132bcce57f7a0a20e317228d382c3cd61edae14650eec68b2b345c
Status: Downloaded newer image for hello-world:latest

Hello from Docker!
This message shows that your installation appears to be working correctly.

При возникновении проблем обратитесь к документации Docker для их устранения.

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

Linux / macOS Windows

Запустим кластер minikube, уже настроенный в начале статьи “Подготовка окружения”:

minikube start

Выставим Namespace по умолчанию, чтобы не указывать его при каждом вызове kubectl:

kubectl config set-context minikube --namespace=werf-guide-app

Результат успешного выполнения команды:

😄  minikube v1.20.0 on Ubuntu 20.04
✨  Using the docker driver based on existing profile
👍  Starting control plane node minikube in cluster minikube
🚜  Pulling base image ...
🎉  minikube 1.21.0 is available! Download it: https://github.com/kubernetes/minikube/releases/tag/v1.21.0
💡  To disable this notice, run: 'minikube config set WantUpdateNotification false'

🔄  Restarting existing docker container for "minikube" ...
🐳  Preparing Kubernetes v1.20.2 on Docker 20.10.6 ...
🔎  Verifying Kubernetes components...
    ▪ Using image gcr.io/google_containers/kube-registry-proxy:0.4
    ▪ Using image k8s.gcr.io/ingress-nginx/controller:v0.44.0
    ▪ Using image registry:2.7.1
    ▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
    ▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
    ▪ Using image gcr.io/k8s-minikube/storage-provisioner:v5
🔎  Verifying registry addon...
🔎  Verifying ingress addon...
🌟  Enabled addons: storage-provisioner, registry, default-storageclass, ingress
🏄  Done! kubectl is now configured to use "minikube" cluster and "werf-guide-app" namespace by default

Убедитесь, что вывод команды содержит строку:

Restarting existing docker container for "minikube"

Если её нет, значит был создан новый кластер minikube вместо использования старого. В таком случае повторите установку рабочего окружения с minikube с самого начала.

Теперь запустите команду в фоновом PowerShell-терминале и не закрывайте его:

minikube tunnel --cleanup=true

Запустим кластер minikube, уже настроенный в начале статьи “Подготовка окружения”:

minikube start --namespace werf-guide-app

Выставим Namespace по умолчанию, чтобы не указывать его при каждом вызове kubectl:

kubectl config set-context minikube --namespace=werf-guide-app

Результат успешного выполнения команды:

😄  minikube v1.20.0 on Ubuntu 20.04
✨  Using the docker driver based on existing profile
👍  Starting control plane node minikube in cluster minikube
🚜  Pulling base image ...
🎉  minikube 1.21.0 is available! Download it: https://github.com/kubernetes/minikube/releases/tag/v1.21.0
💡  To disable this notice, run: 'minikube config set WantUpdateNotification false'

🔄  Restarting existing docker container for "minikube" ...
🐳  Preparing Kubernetes v1.20.2 on Docker 20.10.6 ...
🔎  Verifying Kubernetes components...
    ▪ Using image gcr.io/google_containers/kube-registry-proxy:0.4
    ▪ Using image k8s.gcr.io/ingress-nginx/controller:v0.44.0
    ▪ Using image registry:2.7.1
    ▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
    ▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
    ▪ Using image gcr.io/k8s-minikube/storage-provisioner:v5
🔎  Verifying registry addon...
🔎  Verifying ingress addon...
🌟  Enabled addons: storage-provisioner, registry, default-storageclass, ingress
🏄  Done! kubectl is now configured to use "minikube" cluster and "werf-guide-app" namespace by default

Убедитесь, что вывод команды содержит строку:

Restarting existing docker container for "minikube"

Случайно удаляли Namespace приложения?

Если вы непреднамеренно удалили Namespace приложения, то необходимо выполнить следующие команды, чтобы продолжить прохождение руководства:

kubectl create namespace werf-guide-app
kubectl create secret docker-registry registrysecret \
  --docker-server='https://index.docker.io/v1/' \
  --docker-username='<ИМЯ ПОЛЬЗОВАТЕЛЯ DOCKER HUB>' \
  --docker-password='<ПАРОЛЬ ПОЛЬЗОВАТЕЛЯ DOCKER HUB>'

Результат успешного выполнения команды:

namespace/werf-guide-app created
secret/registrysecret created

Ничего не помогло, окружение или инструкции по-прежнему не работают?

Если ничего не помогло, то пройдите статью «Подготовка окружения» с начала, подготовив новое окружение с нуля. Если и это не помогло, тогда, пожалуйста, расскажите о своей проблеме в нашем Telegram или оставьте Issue на GitHub, и мы обязательно вам поможем.

Подготовка репозитория

Продолжаю проходить руководство Начинаю проходить руководство с этой статьи

Обновим существующий репозиторий с приложением:

Linux / macOS Windows

Выполним следующий набор команд в PowerShell:

cd ~/werf-guide/app

# Чтобы увидеть, какие изменения мы собрались вносить далее в этой статье, заменим все файлы приложения
# в репозитории новыми, уже измененными файлами приложения, которые содержат описанные далее изменения.
git rm -r .
cp -Recurse -Force ~/werf-guide/guides/examples/django/020_logging/* .
git add .
git commit -m WIP

Посмотреть, какие именно изменения мы произведём

# Показать, какие файлы мы собираемся изменить.
git show --stat
# Показать изменения.
git show

Выполним следующий набор команд в Bash:

cd ~/werf-guide/app

# Чтобы увидеть, какие изменения мы собрались вносить далее в этой статье, заменим все файлы приложения
# в репозитории новыми, уже измененными файлами приложения, которые содержат описанные далее изменения.
git rm -r .
cp -rf ~/werf-guide/guides/examples/django/020_logging/. .
git add .
git commit -m WIP

Посмотреть, какие именно изменения мы произведём

# Показать, какие файлы мы собираемся изменить.
git show --stat
# Показать изменения.
git show

Не работает? Попробуйте инструкции на вкладке «Начинаю проходить руководство с этой статьи» выше.

Подготовим новый репозиторий с приложением:

Linux / macOS Windows

Выполним следующий набор команд в PowerShell:

# Склонируем репозиторий с примерами в ~/werf-guide/guides, если он ещё не был склонирован.
if (-not (Test-Path ~/werf-guide/guides)) {
  git clone https://github.com/werf/website $env:HOMEPATH/werf-guide/guides
}

# Скопируем файлы приложения (пока без изменений) в ~/werf-guide/app.
rm -Recurse -Force ~/werf-guide/app
cp -Recurse -Force ~/werf-guide/guides/examples/django/010_basic_app ~/werf-guide/app

# Сделаем из директории ~/werf-guide/app git-репозиторий.
cd ~/werf-guide/app
git init
git add .
git commit -m initial

# Чтобы увидеть, какие изменения мы собрались вносить далее в этой статье, заменим все файлы приложения
# в репозитории новыми, уже измененными файлами приложения, которые содержат описанные далее изменения.
git rm -r .
cp -Recurse -Force ~/werf-guide/guides/examples/django/020_logging/* .
git add .
git commit -m WIP

Посмотреть, какие именно изменения мы произведём

# Показать, какие файлы мы собираемся изменить.
git show --stat
# Показать изменения.
git show

Выполним следующий набор команд в Bash:

# Склонируем репозиторий с примерами в ~/werf-guide/guides, если он ещё не был склонирован.
test -e ~/werf-guide/guides || git clone https://github.com/werf/website ~/werf-guide/guides

# Скопируем файлы приложения (пока без изменений) в ~/werf-guide/app.
rm -rf ~/werf-guide/app
cp -rf ~/werf-guide/guides/examples/django/010_basic_app ~/werf-guide/app

# Сделаем из директории ~/werf-guide/app git-репозиторий.
cd ~/werf-guide/app
git init
git add .
git commit -m initial

# Чтобы увидеть, какие изменения мы собрались вносить далее в этой статье, заменим все файлы приложения
# в репозитории новыми, уже измененными файлами приложения, которые содержат описанные далее изменения.
git rm -r .
cp -rf ~/werf-guide/guides/examples/django/020_logging/. .
git add .
git commit -m WIP

Посмотреть, какие именно изменения мы произведём

# Показать, какие файлы мы собираемся изменить.
git show --stat
# Показать изменения.
git show

Вывод логов в stdout

У задеплоенных в Kubernetes приложений логи всегда должны отправляться в stdout/stderr. Отправка логов в стандартные потоки делает логи доступными для Kubernetes и систем сбора логов, помогает избегать потерь логов при пересоздании контейнеров, а также переполнения логами дисков Kubernetes-узлов при сохранении их в файлах внутри контейнеров.

По умолчанию Django пишет логи в stdout, поэтому для вывода логов не требуется дополнительных действий.

Формат логов

Логи Django-приложения по умолчанию представляют собой обычный текст:

*** Starting uWSGI 2.0.20 (64bit) on [Thu Aug  4 09:45:00 2022] ***
compiled with version: 11.2.0 on 03 August 2022 22:23:29
os: Linux-5.17.0-1013-oem #14-Ubuntu SMP PREEMPT Mon Jul 4 16:11:10 UTC 2022
nodename: thinkpad
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 8
current working directory: /home/user/github/website/examples/django/020_logging/app
detected binary path: /home/user/.local/bin/uwsgi
*** WARNING: you are running uWSGI without its master process manager ***
your processes number limit is 62424
your memory page size is 4096 bytes
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :8000 fd 3
Python version: 3.10.4 (main, Jun 29 2022, 12:14:53) [GCC 11.2.0]
*** Python threads support is disabled. You can enable it with --enable-threads ***
Python main interpreter initialized at 0x560060bfcc40
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 72920 bytes (71 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x560060bfcc40 pid: 150328 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI worker 1 (and the only) (pid: 150328, cores: 1)
[pid: 150328|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 258 bytes} [Thu Aug  4 06:45:03 2022] GET /ping => generated 5 bytes in 2 msecs (HTTP/1.1 200) 6 headers in 205 bytes (1 switches on core 0)

Видно, что обычным текстом выводится как сообщение о запуске приложения, так и сообщение о запросе (мы вызвали curl, как в конце предыдущей главы). Такой текст парсить системами сбора и анализа логов будет очень непросто.

Эту проблему можно решить, если отдавать логи в структурированном формате вроде JSON: система сбора логов обычно очень просто распознает и разбирает JSON-логи, а также корректно обрабатывает логи/сообщения в неожиданных, неструктурированных форматах, которые могут вклиниваться между логами в JSON-формате.

Для этого нужно настроить приложение на вывод логов в формате JSON. Создадим конфигурационный файл uwsgi, в котором опишем формат логов:

app/uwsgi.ini Copy filename Copy text

[uwsgi]
module = app.wsgi:application

http-socket = 0.0.0.0:8000

log-encoder = json {"time":"${unix}", "source":"uwsgi", "message":"${msg}"}
log-encoder = nl

log-format = "address":"%(addr)", "host":"%(json_host)", "method":"%(method)", "uri":"%(json_uri)", "protocol":"%(proto)", "resp_size":%(size), "req_body_size":%(cl), "resp_status":%(status), "resp_time":%(secs)"

log-master = true

[uwsgi] module = app.wsgi:application http-socket = 0.0.0.0:8000 log-encoder = json {"time":"${unix}", "source":"uwsgi", "message":"${msg}"} log-encoder = nl log-format = "address":"%(addr)", "host":"%(json_host)", "method":"%(method)", "uri":"%(json_uri)", "protocol":"%(proto)", "resp_size":%(size), "req_body_size":%(cl), "resp_status":%(status), "resp_time":%(secs)" log-master = true

Добавление поддержки тегирования логов выходит за рамки этого руководства, но может быть реализовано при необходимости.

ОБРАТИТЕ ВНИМАНИЕ! Эти изменения и нижеследующие не нужно выполнять самим, здесь мы просто рассказываем, как получили приложение, которое используется в примере. К выполнению предназначена глава «Проверка работоспособности».

Управление уровнем логирования

По умолчанию уровень логирования приложения для production-окружения задан как INFO. Но иногда возникает необходимость изменить это.

К примеру, при диагностике проблем в production может помочь переключение логирования с info на debug для получения дополнительной отладочной информации. Но если приложение работает в большом количестве реплик, то переключать все реплики приложения на debug может быть не лучшей идеей, т.к. это может сказаться на безопасности, а также сильно увеличить нагрузку на компоненты, ответственные за сбор, хранение и анализ логов.

Решить эту проблему поможет возможность выставлять уровень логирования через переменную окружения. Это позволит, например, запустить рядом с уже существующим Deployment’ом приложения, у которого уровень логирования info, точно такой же Deployment, но в одной реплике и с уровнем логирования debug. Также для этого нового Deployment’а мы можем отключить централизованный сбор логов, если таковой имеется. Всё это в совокупности позволит нам не перегружать системы сбора логов и не сохранять в них потенциально небезопасные отладочные логи.

Возможность указывать уровень логирования через переменную окружения LOG_LEVEL реализуется так:

app/app/settings.py Copy filename Copy text

...
LOG_LEVEL = 'INFO'
if environ.get('LOG_LEVEL') is not None:
    LOG_LEVEL = environ.get('LOG_LEVEL')

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
    },
    'root': {
        'handlers': ['console'],
        'level': LOG_LEVEL,
        'propagate': True,
    },
}

... LOG_LEVEL = 'INFO' if environ.get('LOG_LEVEL') is not None: LOG_LEVEL = environ.get('LOG_LEVEL') LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'handlers': { 'console': { 'class': 'logging.StreamHandler', }, }, 'root': { 'handlers': ['console'], 'level': LOG_LEVEL, 'propagate': True, }, }

Если переменная окружения не указана, будет использован стандартный уровень INFO.

Отображение логов при деплое с werf

По умолчанию werf при деплое показывает логи всех контейнеров приложения и делает это до тех пор, пока они не перейдут в состояние Ready. С помощью специальных werf-аннотаций можно организовать фильтрацию логов и выводить только те строки, которые удовлетворяют заданным шаблонам. В дополнение к этому можно настроить вывод логов только для определённых контейнеров.

К примеру, следующим образом можно отключить вывод контейнера с именем container_name при развёртывании:

annotations:
  werf.io/skip-logs-for-containers: container_name

А в следующем примере показывается, как можно выводить только те строки, которые удовлетворяют заданному регулярному выражению:

annotations:
  werf.io/log-regex: ".*ERROR.*"

Список всех доступных аннотаций можно посмотреть здесь.

Эти аннотации влияют только на то, как логи отображаются при деплое с werf. Они не оказывают никакого влияния на развертываемое приложение или его конфигурацию. Логи по-прежнему доступны в stdout/stderr контейнера в первоначальном виде.

Проверка работоспособности

Теперь попробуем развернуть приложение:

werf converge --repo <ИМЯ ПОЛЬЗОВАТЕЛЯ DOCKER HUB>/werf-guide-app

Ожидаемый результат:

┌ ⛵ image app
│ Use cache image for app/dockerfile
│      name: <ИМЯ ПОЛЬЗОВАТЕЛЯ DOCKER HUB>/werf-guide-app:bffe745a6ab14dac56cdacd3391b880bd2ec6049bae4cae396437d36-1661149059515
│        id: 82580e1e4111
│   created: 2022-08-22 09:17:38 +0000 UTC
│      size: 121.8 MiB
└ ⛵ image app (0.00 seconds)

Release "werf-guide-app" does not exist. Installing it now.

┌ Waiting for resources to become ready
│ ┌ Status progress
│ │ DEPLOYMENT                                                           REPLICAS     AVAILABLE     UP-TO-DATE
│ │ werf-guide-app                                                       1/1          1             1
│ │ │   POD                       READY    RESTARTS     STATUS
│ │ └── guide-app-776fd99c79-n88d 0/1      0            ContainerCreatin
│ │     2                                               g
│ └ Status progress
└ Waiting for resources to become ready (1.47 seconds)

NAME: werf-guide-app
LAST DEPLOYED: Mon Aug 22 09:23:11 2022
LAST PHASE: rollout
LAST STAGE: 0
NAMESPACE: werf-guide-app
STATUS: deployed
REVISION: 1
TEST SUITE: None
Running time 8.05 seconds

Выполним пару запросов для генерации логов:

curl http://werf-guide-app.test/ping       # Вернёт "pong" и код возврата 200.
curl http://werf-guide-app.test/not_found  # Ничего не вернёт, только код возврата 404.

В результате выполнения запросов возвращаемые сервером коды возврата отображаться не будут, но их можно посмотреть в логах. Проверим их:

kubectl -n werf-guide-app logs deploy/werf-guide-app

Ожидаемый результат:

{"time":"1661149868", "source":"uwsgi", "message":"\"address\":\"127.0.0.1\", \"host\":\"-\", \"method\":\"GET\", \"uri\":\"-\", \"protocol\":\"HTTP/1.1\", \"resp_size\":210, \"req_body_size\":0, \"resp_status\":200, \"resp_time\":0.000525\""}
{"time":"1661149870", "source":"uwsgi", "message":"\"address\":\"127.0.0.1\", \"host\":\"-\", \"method\":\"GET\", \"uri\":\"-\", \"protocol\":\"HTTP/1.1\", \"resp_size\":2314, \"req_body_size\":0, \"resp_status\":404, \"resp_time\":0.007921\""}

Как видим, логи теперь отдаются в JSON и легко могут быть распарсены. Некоторые логи по-прежнему отдаются обычным текстом, но главное, что системы сбора логов теперь не будут пытаться распарсить логи приложения и часть других логов так, как будто они имеют один формат: JSON-логи сохранятся отдельно и для них будет возможен поиск/фильтрация только по нужным полям.