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

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

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

Подготовьте рабочее окружение согласно инструкциями главы “Подготовка окружения”, если это ещё не сделано.

Рабочее окружение работало, но перестало? Инструкции из этой главы не работают? Может помочь:

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

Запустим приложение 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 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:

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 для их устранения.

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

Запустим кластер 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"

Если её нет, значит был создан новый кластер minikube вместо использования старого. В таком случае повторите установку рабочего окружения с 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, и мы обязательно вам поможем.

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

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

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

cd ~/werf-guide/app

# Чтобы увидеть, какие изменения мы собрались вносить далее в этой главе, заменим все файлы приложения
# в репозитории новыми, уже измененными файлами приложения, которые содержат описанные далее изменения.
git rm -r .
cp -Recurse -Force ~/werf-guide/guides/examples/laravel/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/laravel/020_logging/. .
git add .
git commit -m WIP
Посмотреть, какие именно изменения мы произведём
# Показать, какие файлы мы собираемся изменить
git show --stat
# Показать изменения
git show

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

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

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

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

# Скопируем файлы приложения (пока без изменений) в ~/werf-guide/app
rm -Recurse -Force ~/werf-guide/app
cp -Recurse -Force ~/werf-guide/guides/examples/laravel/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/laravel/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/werf-guides ~/werf-guide/guides

# Скопируем файлы приложения (пока без изменений) в ~/werf-guide/app
rm -rf ~/werf-guide/app
cp -rf ~/werf-guide/guides/examples/laravel/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/laravel/020_logging/. .
git add .
git commit -m WIP
Посмотреть, какие именно изменения мы произведём
# Показать, какие файлы мы собираемся изменить
git show --stat
# Показать изменения
git show

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

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

По умолчанию Laravel не пишет логи ни в stdout, ни в stderr, а сохраняет их в файл. При использовании стандартной конфигурации необходимо использовать переменную окружения LOG_CHANNEL=stderr, чтобы включить вывод всех логов (в т.ч. ошибок) в stderr.

Формат логов

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

[07-Oct-2021 12:36:42] NOTICE: fpm is running, pid 1
[07-Oct-2021 12:36:42] NOTICE: ready to handle connections
[2021-10-07 14:06:17] production.INFO: Ping request.
- -  07/Oct/2021:14:06:17 +0000 "GET /index.php" 200

Обратите внимание, что сообщения от php-fpm и laravel-приложения имеют разный формат, а так же в логе вместо реального запроса /ping отображается SCRIPT_FILENAME из параметров fastcgi. К тому-же такой текст парсить системами сбора и анализа логов будет очень непросто.

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

Чтобы laravel начал отдавать логи в JSON вместо plain text, в стандартной конфигурации, необходимо использовать переменную окружения LOG_STDERR_FORMATTER=Monolog\\Formatter\\JsonFormatter.

Так же зададим JSON формат и для access-логов php-fpm:

[www]
listen = /var/run/php/php-fpm.sock
listen.owner = nobody
listen.group = nobody
access.format='{"time_local":"%{%Y-%m-%dT%H:%M:%S%z}T","client_ip":"%{HTTP_X_FORWARDED_FOR}e","remote_addr":"%R","remote_user":"%u","request":"%m %{REQUEST_URI}e %{SERVER_PROTOCOL}e","status":"%s","body_bytes_sent":"%l","request_time":"%d","http_referrer":"%{HTTP_REFERER}e","http_user_agent":"%{HTTP_USER_AGENT}e","request_id":"%{HTTP_X_REQUEST_ID}e"}'
[www] listen = /var/run/php/php-fpm.sock listen.owner = nobody listen.group = nobody access.format='{"time_local":"%{%Y-%m-%dT%H:%M:%S%z}T","client_ip":"%{HTTP_X_FORWARDED_FOR}e","remote_addr":"%R","remote_user":"%u","request":"%m %{REQUEST_URI}e %{SERVER_PROTOCOL}e","status":"%s","body_bytes_sent":"%l","request_time":"%d","http_referrer":"%{HTTP_REFERER}e","http_user_agent":"%{HTTP_USER_AGENT}e","request_id":"%{HTTP_X_REQUEST_ID}e"}'

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

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

По умолчанию уровень логирования приложения задан как debug. Но в production вы скорее всего захотите info.

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

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

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

...
- name: LOG_LEVEL
  value: info
... - name: LOG_LEVEL value: info

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

Отображение логов при деплое с 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 backend
│ ┌ Building stage backend/dockerfile
│ │ backend/dockerfile  Sending build context to Docker daemon    490kB
│ │ backend/dockerfile  Step 1/18 : FROM php:8.0-fpm-alpine as backend
│ │ backend/dockerfile   ---> 52c511f481c5
...
│ │ backend/dockerfile  Successfully built d3ad86893808
│ │ backend/dockerfile  Successfully tagged 894dff63-2ffb-4311-807b-6ff1f38415bb:latest
│ ├ Info
│ │      name: .../werf-guide-app:f2b022ecef61a8b08f36147c3fd832a1b179bd9144f8f94be1c9920b-1633617910563
│ │        id: d3ad86893808
│ │   created: 2021-10-07 17:45:10 +0300 MSK
│ │      size: 48.8 MiB
│ └ Building stage backend/dockerfile (17.00 seconds)
└ ⛵ image backend (21.54 seconds)

┌ ⛵ image frontend
│ ┌ Building stage frontend/dockerfile
│ │ frontend/dockerfile  Sending build context to Docker daemon    490kB
│ │ frontend/dockerfile  Step 1/23 : FROM php:8.0-fpm-alpine as backend
│ │ frontend/dockerfile   ---> 52c511f481c5
...
│ │ frontend/dockerfile  Successfully built bf8f27681b68
│ │ frontend/dockerfile  Successfully tagged d9147ff4-9a3e-46df-9f5a-45e13b666f21:latest
│ ├ Info
│ │      name: .../werf-guide-app:d1508f77a2abe02adefbe3f5653cc9b1978297d9fbcfc2716800b80d-1633617910174
│ │        id: bf8f27681b68
│ │   created: 2021-10-07 17:45:10 +0300 MSK
│ │      size: 9.4 MiB
│ └ Building stage frontend/dockerfile (12.85 seconds)
└ ⛵ image frontend (17.58 seconds)

┌ Waiting for release resources to become ready
│ ┌ Status progress
│ │ DEPLOYMENT                                                                                      REPLICAS          AVAILABLE           UP-TO-DATE
│ │ werf-guide-app                                                                                  2->1/1            1                   1
│ │ │   POD                                 READY        RESTARTS          STATUS
│ │ ├── guide-app-57489dcc89-5js95          2/2          0                 ContainerCreating ->
│ │ │                                                                      Running
│ │ └── guide-app-58497f7ccb-96tl6          2/2          0                 Running -> Terminating
│ └ Status progress
└ Waiting for release resources to become ready (8.32 seconds)

Release "werf-guide-app" has been upgraded. Happy Helming!
NAME: werf-guide-app
LAST DEPLOYED: Thu Oct  7 17:45:29 2021
NAMESPACE: werf-guide-app
STATUS: deployed
REVISION: 11
TEST SUITE: None
Running time 41.58 seconds
... ┌ ⛵ image backend │ ┌ Building stage backend/dockerfile │ │ backend/dockerfile Sending build context to Docker daemon 490kB │ │ backend/dockerfile Step 1/18 : FROM php:8.0-fpm-alpine as backend │ │ backend/dockerfile ---> 52c511f481c5 ... │ │ backend/dockerfile Successfully built d3ad86893808 │ │ backend/dockerfile Successfully tagged 894dff63-2ffb-4311-807b-6ff1f38415bb:latest │ ├ Info │ │ name: .../werf-guide-app:f2b022ecef61a8b08f36147c3fd832a1b179bd9144f8f94be1c9920b-1633617910563 │ │ id: d3ad86893808 │ │ created: 2021-10-07 17:45:10 +0300 MSK │ │ size: 48.8 MiB │ └ Building stage backend/dockerfile (17.00 seconds) └ ⛵ image backend (21.54 seconds) ┌ ⛵ image frontend │ ┌ Building stage frontend/dockerfile │ │ frontend/dockerfile Sending build context to Docker daemon 490kB │ │ frontend/dockerfile Step 1/23 : FROM php:8.0-fpm-alpine as backend │ │ frontend/dockerfile ---> 52c511f481c5 ... │ │ frontend/dockerfile Successfully built bf8f27681b68 │ │ frontend/dockerfile Successfully tagged d9147ff4-9a3e-46df-9f5a-45e13b666f21:latest │ ├ Info │ │ name: .../werf-guide-app:d1508f77a2abe02adefbe3f5653cc9b1978297d9fbcfc2716800b80d-1633617910174 │ │ id: bf8f27681b68 │ │ created: 2021-10-07 17:45:10 +0300 MSK │ │ size: 9.4 MiB │ └ Building stage frontend/dockerfile (12.85 seconds) └ ⛵ image frontend (17.58 seconds) ┌ Waiting for release resources to become ready │ ┌ Status progress │ │ DEPLOYMENT REPLICAS AVAILABLE UP-TO-DATE │ │ werf-guide-app 2->1/1 1 1 │ │ │ POD READY RESTARTS STATUS │ │ ├── guide-app-57489dcc89-5js95 2/2 0 ContainerCreating -> │ │ │ Running │ │ └── guide-app-58497f7ccb-96tl6 2/2 0 Running -> Terminating │ └ Status progress └ Waiting for release resources to become ready (8.32 seconds) Release "werf-guide-app" has been upgraded. Happy Helming! NAME: werf-guide-app LAST DEPLOYED: Thu Oct 7 17:45:29 2021 NAMESPACE: werf-guide-app STATUS: deployed REVISION: 11 TEST SUITE: None Running time 41.58 seconds

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

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

Проверим логи:

kubectl logs deploy/werf-guide-app -c backend

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

[07-Oct-2021 14:45:35] NOTICE: fpm is running, pid 1
[07-Oct-2021 14:45:35] NOTICE: ready to handle connections
{"message":"Ping request.","context":{},"level":200,"level_name":"INFO","channel":"production","datetime":"2021-10-07T14:48:13.808904+00:00","extra":{}}
{"time_local":"2021-10-07T14:48:13+0000","client_ip":"192.168.49.1","remote_addr":"-","remote_user":"","request":"GET /ping HTTP/1.1","status":"200","body_bytes_sent":"0","request_time":"0.171","http_referrer":"-","http_user_agent":"curl/7.64.1","request_id":"52e2b175bb93949f2901cd27f297e057"}
{"time_local":"2021-10-07T14:48:18+0000","client_ip":"192.168.49.1","remote_addr":"-","remote_user":"","request":"GET /not_found HTTP/1.1","status":"404","body_bytes_sent":"0","request_time":"0.039","http_referrer":"-","http_user_agent":"curl/7.64.1","request_id":"a7d81d60362b0597f8992e290cd78a10"}

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