В этой статье мы настроим логирование приложения в Kubernetes и разберём его особенности, а также сделаем структурированный формат логов для последующего парсинга системами сбора и анализа логов.
Приложение в этой статье не предназначено для использования в production без доработки. Готовое к работе в production приложение мы получим в конце руководства.
Подготовка окружения
Если вы ещё не подготовили своё рабочее окружение на предыдущих этапах, сделайте это в соответствии с инструкциями статьи «Подготовка окружения».
Если ваше рабочее окружение работало, но перестало, или же последующие инструкции из этой статьи не работают — попробуйте следующее:
Запустим приложение 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 приложения, то необходимо выполнить следующие команды, чтобы продолжить прохождение руководства:
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/nodejs/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/nodejs/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/website $env:HOMEPATH/werf-guide/guides
}
# Скопируем файлы приложения (пока без изменений) в ~/werf-guide/app.
rm -Recurse -Force ~/werf-guide/app
cp -Recurse -Force ~/werf-guide/guides/examples/nodejs/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/nodejs/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/nodejs/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/nodejs/020_logging/. .
git add .
git commit -m WIP
# Показать, какие файлы мы собираемся изменить.
git show --stat
# Показать изменения.
git show
Вывод логов в stdout
У запущенных в Kubernetes приложений логи всегда должны отправляться в stdout/stderr. Отправка логов в стандартные потоки делает логи доступными для Kubernetes и систем сбора логов, помогает избегать потерь логов при пересоздании контейнеров, а также переполнения логами дисков Kubernetes-узлов при сохранении их в файлах внутри контейнеров.
По умолчанию express пишет логи в stdout, поэтому для вывода логов не требуется дополнительных действий.
Формат логов
Логи Node.js-приложения по умолчанию представляют собой обычный текст:
> app@0.0.0 start /app
> node ./bin/www
Thu, 11 Nov 2021 15:06:10 GMT app:server Listening on port 3000
GET /ping 200 6.086 ms - 5
Видно, что обычным текстом выводится как сообщение о запуске приложения, так и сообщение о запросе (мы вызвали curl, как в конце предыдущей главы). Такой текст парсить системами сбора и анализа логов будет очень непросто.
Эту проблему можно решить, если отдавать логи в структурированном формате вроде JSON: система сбора логов обычно очень просто распознает и разбирает JSON-логи, а также корректно обрабатывает логи/сообщения в неожиданных, неструктурированных форматах, которые могут вклиниваться между логами в JSON-формате.
Для этого нужно использовать логгер, который поддерживает вывод в JSON. Для примера возьмем pino и
заодно удалим логгер, который используется по умолчанию:
$ npm uninstall morgan
$ npm install pino pino-http
Подключим логгер к серверу:
...
const pino = require('pino');
const pinoHttp = require('pino-http');
...
app.use(
pinoHttp({
// Зададим уровень логирования, который мы используем в других компонентах с помощью res.log.
logger: pino({ level: process.env.LOG_LEVEL || 'info' }),
// Для сервера зададим фиксированный уровень логирования.
useLevel: 'info',
})
);
Библиотека pino-http добавила доступ к pino через объект ответа: res.log. Так логгер можно
инициализировать один раз и использовать как зависимость в другом коде:
...
router.get('/', function (req, res, next) {
res.log.debug('we are being pinged');
res.send('pong\n');
});
Добавление поддержки тегирования логов выходит за рамки этого руководства, но может быть реализовано при необходимости.
Теперь, если сделать запрос на маршрут /ping, в выводе будут две JSON-строки:
{"level":20,"time":1636645957094,"pid":1,"hostname":"werf-guide-app-d47fd67f9-qln6t","req":{"id":4,"method":"GET","url":"/ping","query":{},"params":{},"headers":{"host":"werf-guide-app.test","x-request-id":"17ff378b3d2068788b21bb702856cdee","x-real-ip":"192.168.64.1","x-forwarded-for":"192.168.64.1","x-forwarded-host":"werf-guide-app.test","x-forwarded-port":"80","x-forwarded-proto":"http","x-forwarded-scheme":"http","x-scheme":"http","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::ffff:172.17.0.2","remotePort":42204},"msg":"we are being pinged"}
{"level":30,"time":1636645957097,"pid":1,"hostname":"werf-guide-app-d47fd67f9-qln6t","req":{"id":4,"method":"GET","url":"/ping","query":{},"params":{},"headers":{"host":"werf-guide-app.test","x-request-id":"17ff378b3d2068788b21bb702856cdee","x-real-ip":"192.168.64.1","x-forwarded-for":"192.168.64.1","x-forwarded-host":"werf-guide-app.test","x-forwarded-port":"80","x-forwarded-proto":"http","x-forwarded-scheme":"http","x-scheme":"http","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::ffff:172.17.0.2","remotePort":42204},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"5","etag":"W/\"5-dv2B8tXZGrCcINvgl7S82poObJs\""}},"responseTime":3,"msg":"request completed"}
За счет pino мы смогли сконвертировать логи сервера в JSON. Но это не повлияло на лог от npm, с помощью которого мы запускаем приложение в Pod’е. Чтобы избавиться от ненужного лога, можно запустить приложение минуя npm:
...
command: ["node", "./bin/www"]
ОБРАТИТЕ ВНИМАНИЕ! Эти изменения и нижеследующие не нужно выполнять самим, здесь мы просто рассказываем, как получили приложение, которое используется в примере. К выполнению предназначена глава «Проверка работоспособности».
Управление уровнем логирования
По умолчанию уровень логирования приложения для production-окружения задан как info. Но иногда возникает необходимость изменить это.
К примеру, при диагностике проблем в production может помочь переключение логирования с info на debug для получения дополнительной отладочной информации. Но если приложение работает в большом количестве реплик, то переключать все реплики приложения на debug может быть не лучшей идеей, т.к. это может сказаться на безопасности, а также сильно увеличить нагрузку на компоненты, ответственные за сбор, хранение и анализ логов.
Решить эту проблему поможет возможность выставлять уровень логирования через переменную окружения. Это позволит, например, запустить рядом с уже существующим Deployment’ом приложения, у которого уровень логирования info, точно такой же Deployment, но в одной реплике и с уровнем логирования debug. Также для этого нового Deployment’а мы можем отключить централизованный сбор логов, если таковой имеется. Всё это в совокупности позволит нам не перегружать системы сбора логов и не сохранять в них потенциально небезопасные отладочные логи.
Возможность указывать уровень логирования через переменную окружения LOG_LEVEL реализуется так:
...
env:
- name: NODE_ENV
value: production
- name: LOG_LEVEL
value: debug
Мы сами определили переменную окружения для управления уровнем логирования. Несмотря на то, что мы также сами определили уровень info по умолчанию, это поведение в pino реализовано изначально:
...
app.use(
pinoHttp({
// Зададим уровень логирования, который мы используем в других компонентах с помощью res.log.
logger: pino({ level: process.env.LOG_LEVEL || 'info' }),
// Для сервера зададим фиксированный уровень логирования.
useLevel: 'info',
})
);
Если переменная окружения не указана, будет использован стандартный уровень 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:a0c674d1d0378b6c53b8694be1688c2b454e892105a6850e7d5b074c-1636644540936
│ id: 37e64591badb
│ created: 2022-11-11 18:29:00 +0000 UTC
│ size: 30.3 MiB
└ ⛵ image app (8.03 seconds)
┌ Waiting for release 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-6c6c4dbf6-wxr6k 1/1 0 Terminating
│ │ └── guide-app-d47fd67f9-hq2ds 1/1 0 Running
│ └ Status progress
└ Waiting for release resources to become ready (1.94 seconds)
Release "werf-guide-app" has been upgraded. Happy Helming!
NAME: werf-guide-app
LAST DEPLOYED: Thu Nov 11 18:30:47 2022
NAMESPACE: werf-guide-app
STATUS: deployed
REVISION: 3
TEST SUITE: None
Running time 15.69 seconds
Выполним пару запросов для генерации логов:
curl http://werf-guide-app.test/ping # Вернёт "pong" и код возврата 200.
curl http://werf-guide-app.test/not_found # Ничего не вернёт, только код возврата 404.
В результате выполнения запросов возвращаемые сервером коды возврата отображаться не будут, но их можно посмотреть в логах. Проверим их:
kubectl logs deploy/werf-guide-app
Ожидаемый результат:
{"level":20,"time":1636647707471,"pid":1,"hostname":"werf-guide-app-d47fd67f9-qln6t","req":{"id":7,"method":"GET","url":"/ping","query":{},"params":{},"headers":{"host":"werf-guide-app.test","x-request-id":"a7bda9916010a7547682c14a7f1d3c93","x-real-ip":"192.168.64.1","x-forwarded-for":"192.168.64.1","x-forwarded-host":"werf-guide-app.test","x-forwarded-port":"80","x-forwarded-proto":"http","x-forwarded-scheme":"http","x-scheme":"http","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::ffff:172.17.0.2","remotePort":52936},"msg":"we are being pinged"}
{"level":30,"time":1636647707472,"pid":1,"hostname":"werf-guide-app-d47fd67f9-qln6t","req":{"id":7,"method":"GET","url":"/ping","query":{},"params":{},"headers":{"host":"werf-guide-app.test","x-request-id":"a7bda9916010a7547682c14a7f1d3c93","x-real-ip":"192.168.64.1","x-forwarded-for":"192.168.64.1","x-forwarded-host":"werf-guide-app.test","x-forwarded-port":"80","x-forwarded-proto":"http","x-forwarded-scheme":"http","x-scheme":"http","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::ffff:172.17.0.2","remotePort":52936},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"5","etag":"W/\"5-dv2B8tXZGrCcINvgl7S82poObJs\""}},"responseTime":1,"msg":"request completed"}
{"level":30,"time":1636647710678,"pid":1,"hostname":"werf-guide-app-d47fd67f9-qln6t","req":{"id":8,"method":"GET","url":"/not_found","query":{},"params":{},"headers":{"host":"werf-guide-app.test","x-request-id":"abc9b62a1f9ba9a490dbfa6e82471bf8","x-real-ip":"192.168.64.1","x-forwarded-for":"192.168.64.1","x-forwarded-host":"werf-guide-app.test","x-forwarded-port":"80","x-forwarded-proto":"http","x-forwarded-scheme":"http","x-scheme":"http","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::ffff:172.17.0.2","remotePort":52958},"res":{"statusCode":404,"headers":{"x-powered-by":"Express","content-security-policy":"default-src 'self'","x-content-type-options":"nosniff","content-type":"text/html; charset=utf-8","content-length":148}},"responseTime":1,"msg":"request completed"}
Как видим, логи теперь отдаются в JSON и легко могут быть распарсены. Некоторые логи по-прежнему отдаются обычным текстом, но главное, что системы сбора логов теперь не будут пытаться распарсить логи приложения и часть других логов так, как будто они имеют один формат: JSON-логи сохранятся отдельно и для них будет возможен поиск/фильтрация только по нужным полям.
