Чтение сбоя по логам
При сбое сервиса или загрузки: journalctl -u svc -b -p err, найти ПЕРВУЮ ошибку, а не последнюю, скоррелировать временные метки по юнитам, проверить systemctl status для кода завершения. Погоня за последней ошибкой — самая частая ошибка при чтении логов.
Сервис падает в 2:47 ночи. К 9 утра, когда ты открываешь логи, там тысячи строк: шторм повторных попыток, таймауты watchdog, каскады зависимых сервисов, сообщения OOM ядра — и наконец чистый перезапуск, скрывший исходную проблему. Последняя ошибка в логе — «connection refused». Это не причина — это симптом. Причина — тремя минутами раньше: неправильно настроенная переменная окружения, из-за которой процесс завершился с кодом 1 при старте. Самая дорогостоящая ошибка оператора — погоня за последней ошибкой. Навык этого урока — найти первую ошибку, скоррелировать её по юнитам и прочитать временную шкалу сбоя в обратном порядке — от симптома к первопричине.
После этого урока ты сможешь применять структурированный операторский рабочий процесс для диагностики сбоя сервиса или загрузки по логам journald: определить область через systemctl status, получить окно ошибок через journalctl -u -b -p err --since, найти первую ошибку, скоррелировать временные метки по юнитам и отличить первопричину от каскадных симптомов.
Начни с systemctl status — он даёт код завершения и последний снипет.
До открытия полного журнала systemctl status даёт два критически важных элемента: код завершения и последние 10 строк журнала. Они определяют область расследования.
# Проверить статус упавшего сервиса:
systemctl status myapp.service
# ● myapp.service - My Application
# Loaded: loaded (/etc/systemd/system/myapp.service; enabled)
# Active: failed (Result: exit-code) since Mon 2024-03-18 02:47:13 UTC; 6h ago
# Process: 3821 ExecStart=/usr/bin/myapp (code=exited, status=1/FAILURE)
# Main PID: 3821 (code=exited, status=1/FAILURE)
#
# Mar 18 02:47:13 host myapp[3821]: connection to database refused
# Mar 18 02:47:13 host systemd[1]: myapp.service: Main process exited, code=exited, status=1
# Mar 18 02:47:13 host systemd[1]: Failed to start My Application.
# Извлечённая ключевая информация:
# - Код завершения: status=1/FAILURE (приложение вышло с ненулевым кодом, не убито сигналом)
# - Временная метка: 02:47:13 — якорь для запроса журнала
# - Последнее сообщение: "connection to database refused" — симптом, не причина
# Другие значения Result:
# Result: exit-code → процесс вышел с ненулевым кодом
# Result: signal → процесс убит сигналом (напр. OOM killer → SIGKILL)
# Result: timeout → ExecStart превысил таймаут
# Result: core-dump → процесс упал с дампом ядраКод завершения говорит о режиме сбоя. exit-code со status=1 — ошибка приложения. signal с SIGKILL часто означает OOM. timeout означает, что процесс не сигнализировал о готовности в течение TimeoutStartSec.
Получи окно ошибок: -b -p err --since.
Теперь запроси журнал для полной картины вокруг времени сбоя:
# Получить ошибки текущей загрузки для этого юнита:
journalctl -u myapp.service -b -p err
# Mar 18 02:44:01 host myapp[3821]: WARN: DATABASE_URL not set, using default
# Mar 18 02:44:01 host myapp[3821]: ERR: failed to connect: dial tcp 127.0.0.1:5432: refused
# Mar 18 02:47:13 host myapp[3821]: connection to database refused
# Mar 18 02:47:13 host systemd[1]: myapp.service: Main process exited, code=exited, status=1
# Замечаем: ПЕРВАЯ ошибка в 02:44:01 — за три минуты до окончательного сбоя.
# Приложение повторяло попытки 3 минуты до того, как systemd пометил его как упавший.
# Расширить до info для просмотра цикла повторных попыток:
journalctl -u myapp.service -b -p info --since "02:43:00" --until "02:48:00"
# 02:44:01 WARN: DATABASE_URL not set, using default ← ПЕРВОПРИЧИНА
# 02:44:01 ERR: failed to connect: dial tcp 127.0.0.1:5432
# 02:44:06 INFO: retrying connection (attempt 2/10)
# 02:44:16 INFO: retrying connection (attempt 3/10)
# ...
# 02:47:13 ERR: connection to database refused ← СИМПТОМ (последняя ошибка)
# 02:47:13 systemd: Main process exited
# Первопричина ясна: DATABASE_URL не задан, приложение подключается к
# 127.0.0.1:5432 (умолчание), где нет PostgreSQL.Паттерн: ошибки в начале окна ошибок — первопричины. Ошибки в конце — симптомы каскада. Всегда читай окно ошибок сверху вниз, не снизу вверх.
Корреляция по юнитам: сбой редко живёт в одном сервисе.
Сервисы зависят друг от друга. Сбой подключения к БД может быть вызван тем, что postgres не запустился. Запроси журнал зависимости в том же временном окне.
# Проверить, работал ли postgres в 02:44:
journalctl -u postgresql.service -b -p err --since "02:40:00" --until "02:48:00"
# Mar 18 02:43:47 host postgres[3712]: FATAL: data directory "/var/lib/postgresql/14/main"
# has wrong ownership
# Mar 18 02:43:47 host systemd[1]: postgresql.service: Main process exited, code=exited, status=1
# Mar 18 02:43:47 host systemd[1]: Failed to start PostgreSQL Database Server.
# Postgres упал за 14 секунд до того, как myapp попытался подключиться.
# Проблема с владельцем директории данных — настоящая первопричина.
# Реконструкция межюнитной временной шкалы:
journalctl -b -p err --since "02:43:00" --until "02:48:00"
# (показывает ВСЕ юниты в этом окне, в хронологическом порядке)
# 02:43:47 postgresql: FATAL: data directory has wrong ownership
# 02:43:47 systemd: postgresql.service: Failed to start
# 02:44:01 myapp: DATABASE_URL not set (вторичная проблема)
# 02:44:01 myapp: failed to connect: 127.0.0.1:5432 refused
# 02:47:13 myapp: Main process exited
# Полная причинно-следственная цепочка:
# 1. Неправильный владелец директории postgres → postgres не запускается
# 2. myapp стартует, DATABASE_URL не задан → подключается к localhost (неверно)
# 3. На localhost нет postgres → connection refused → myapp падает после попытокЗапрос по нескольким юнитам (journalctl -b -p err --since ... --until ... без -u) показывает полную системную временную шкалу. Так реконструируется каскад.
Сбои загрузки: чтение последовательности запуска.
Когда система не достигает цели (например, зависает при загрузке), подход тот же, но запрашиваешь предыдущую загрузку через -b -1.
# Список загрузок для подтверждения предыдущей:
journalctl --list-boots
# -1 abc123... Mon 2024-03-18 02:43:00 → Mon 2024-03-18 02:47:15 (краш/перезагрузка)
# 0 def456... Mon 2024-03-18 02:48:00 → Mon 2024-03-18 09:12:00 (текущая)
# Все ошибки предыдущей (упавшей) загрузки:
journalctl -b -1 -p err
# Mar 18 02:43:47 host kernel: EXT4-fs error (device sda1): ...
# Mar 18 02:43:47 host postgres: FATAL: data directory has wrong ownership
# Mar 18 02:43:47 host systemd: postgresql.service: Failed
# Mar 18 02:43:48 host systemd: Job postgresql.service/start failed
# Какой юнит заблокировал цель загрузки:
journalctl -b -1 | grep -E "Failed|Timed out|reached target"
# systemd: Failed to start PostgreSQL Database Server.
# systemd: Reached target Basic System. ← базовая система OK
# systemd: multi-user.target: Job timed out ← загрузка зависла здесь
# ExecStartPre-сбои — особенно частые убийцы загрузки:
journalctl -b -1 -u myapp.service | grep -i "pre\|exec\|failed"
# ExecStartPre=/usr/bin/check-config.sh (code=exited, status=1/FAILURE)
# Main process exited before ExecStart ranСбои ExecStartPre — тихие убийцы загрузки: основной процесс никогда не запускается, поэтому нет логов приложения — только строка systemd о сбое скрипта предпроверки. Всегда проверяй ExecStartPre в файле юнита, если сервис не генерирует никаких логов.
Сообщения ядра и события OOM.
Некоторые сбои происходят в ядре: OOM-убийства, ошибки файловой системы, сбросы сетевого драйвера. Они появляются в журнале под транспортом kernel.
# Сообщения ядра текущей загрузки (все уровни):
journalctl -k -b
# Только ошибки ядра:
journalctl -k -b -p err
# Mar 18 03:15:22 host kernel: Out of memory: Killed process 4921 (myapp) total-vm:2048000kB
# Mar 18 03:15:22 host kernel: oom_kill_process+0x...
# Корреляция: что произошло сразу после OOM-убийства?
journalctl -b -p err --since "03:15:20" --until "03:15:30"
# 03:15:22 kernel: Out of memory: Killed process 4921 (myapp)
# 03:15:22 systemd: myapp.service: Main process exited, code=killed, status=9/KILL
# 03:15:22 systemd: myapp.service: Failed with result 'signal'.
# Result: signal и status=9/KILL подтверждают OOM — не баг в приложении.
# Проверить oom_score для запущенного процесса (предвидеть будущие OOM-убийства):
cat /proc/$(pgrep myapp)/oom_score
# 847 ← высокий балл = выше вероятность убийства при следующем OOM
# Защитить критический процесс (установить -500; требует root):
echo -500 | sudo tee /proc/$(pgrep myapp)/oom_score_adjОтпечаток Result: signal с status=9/KILL — сигнатура OOM-убийства. Строка лога ядра непосредственно выше (в пределах той же секунды) подтверждает это. Без чтения обоих слоёв — ядра и systemd — можно подумать, что приложение упало, а не было убито.
Полный разбор инцидента: приложение падает каждую ночь в 2 ночи.
Сообщения: payment-worker.service падает каждую ночь около 2 ночи, восстанавливается при перезапуске, но транзакции теряются в окне отказа.
# Шаг 1: определить область через systemctl status
systemctl status payment-worker.service
# Active: failed (Result: exit-code) since Tue 2024-03-19 02:01:44 UTC; 7h ago
# Process: 7823 ExecStart=... (code=exited, status=137/FAILURE)
# status=137 = 128 + 9 = убит сигналом 9 (SIGKILL)
# Шаг 2: получить ошибки
journalctl -u payment-worker.service -b -1 -p err
# Mar 19 01:58:11 payment-worker: heap allocation failed: cannot allocate 512MB
# Mar 19 01:58:11 payment-worker: fatal: out of memory, shutting down
# Mar 19 02:01:44 systemd: payment-worker: Main process exited, status=137
# Шаг 3: корреляция — проверить OOM ядра в то же время
journalctl -k -b -1 -p err --since "01:57:00" --until "02:02:00"
# Mar 19 01:58:10 kernel: Out of memory: Killed process 7712 (redis-server) total-vm:...
# Ядро убило redis за секунду ДО того, как payment-worker залогировал "out of memory"
# Полная картина:
# 01:58:10 OOM-убийца убивает redis (redis использовал 600MB, payment-worker нужно 512MB)
# 01:58:11 payment-worker пытается выделить 512MB → не может (физическая память исчерпана)
# 01:58:11 payment-worker завершается сам с кодом 137
# Шаг 4: подтвердить ночной паттерн
journalctl --list-boots | head -5
# -4 ... Tue 2024-03-15 02:01 → ...
# -3 ... Wed 2024-03-16 02:00 → ...
# Одно и то же время каждую ночь → память растёт до 2 ночи, затем OOM
# Первопричина: утечка памяти в payment-worker; redis — случайный пострадавший.
# Исправление: добавить SystemMaxMemory=400M в файл юнита как временный
# ограничитель и отслеживать рост кучи в мониторинге.▸Частая ошибка
Погоня за последней ошибкой — самая дорогостоящая ошибка при чтении логов. В каскаде последняя ошибка всегда симптом: «connection refused», «timeout», «address already in use». Это то, что выводил падающий сервис в агонии. Первопричина всегда раньше: зависимость, с которой всё началось. Тренируйся читать окно ошибок с начала (самая ранняя ошибка) и воспринимай конец как шум, пока не нашёл источник. Полезная эвристика: если первая и последняя ошибки — одно и то же сообщение, ты нашёл первопричину. Если они разные — ты ещё в каскаде.
▸Почему это работает
Почему --since + --until лучше прокрутки. На нагруженной системе journalctl -b -p err без временных границ может вернуть тысячи строк за несколько часов. Привязка к --since и --until вокруг временной метки сбоя (из systemctl status) ограничивает окно нужными 2–5 минутами. Это целевой бинарный поиск, а не линейная прокрутка. Временная метка сбоя из systemctl status — твой якорь; всегда начинай с него.
Сервис упал. journalctl -u svc -b -p err показывает 40 строк. Первая строка (02:44:01): 'config file not found'. Последняя строка (02:47:13): 'connection to database refused'. Что является первопричиной и почему?
Операторский рабочий процесс для упавшего сервиса: systemctl status даёт код завершения (exit-code, signal, timeout, core-dump) и якорь временной метки. journalctl -u svc -b -p err получает окно ошибок — читай его сверху вниз, потому что первая ошибка — первопричина, а последняя — симптом каскада. --since/--until ограничивает окно нужными минутами. Межюнитная корреляция (journalctl -b -p err --since ... --until ... без -u) реконструирует полный каскад зависимостей. journalctl -k -b -p err добавляет события ядра: OOM-убийства видны как Result: signal + status=9/KILL со строкой лога ядра секундой раньше. Сбои ExecStartPre не генерируют логов приложения — если сервис ничего не выводит, проверь скрипт предпроверки в файле юнита. Дисциплина: ищи первую ошибку, а не последнюю.
Практика
Начни сверху. Задачи идут от простого к сложному: вспомнить факт, применить к случаю, затем senior-уровень. Открой, попробуй, потом открой ответ.
Что-то непонятно?
Задай вопрос по этому уроку. Вопросы анонимны и попадают напрямую автору — урок станет лучше.
Примени это
Примени этот урок в реальном проекте.