Разбор инцидента: как найти причину сбоя по логам

Анатомия инцидента: от симптома к причине

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

> ℹ️ Информация: В 90% случаев причина сбоя кроется не в отказе оборудования, а в логике сценариев, ошибках конфигурации или непредусмотренных изменениях во внешней среде (например, обновление прошивки устройства стороннего производителя). Логи — ваш главный и зачастую единственный инструмент для обнаружения таких проблем.

Ключевая задача инженера при разборе инцидента — отличить симптом от первопричины.

• Симптом — это внешнее проявление проблемы, то, на что жалуется пользователь. Например: "свет в коридоре не включился, когда я вошел", "отопление не запустилось утром", "шторы не закрылись на закате". Симптомы часто эмоциональны, неточны во времени и описывают лишь конечный результат сбоя.

• Первопричина — это конкретное техническое событие или состояние, которое запустило цепочку отказов, приведшую к наблюдаемому симптому. Например: "датчик движения отправил сообщение в некорректном формате JSON", "задача по расписанию не запустилась из-за сбоя службы cron", "истек таймаут при запросе к Modbus-счетчику".

Полагаться на описание симптома от пользователя для поиска решения — это путь к долгой и безрезультатной диагностике. Единственным источником объективной правды для post-mortem анализа (анализа инцидента "после вскрытия") являются журналы событий или логи. Только в них зафиксирована точная хронология, значения переменных, команды и ошибки, которые происходили в системе в момент сбоя.

Эффективный разбор инцидента всегда следует системной методологии:

Сформулировать гипотезу. На основе симптома выдвигается наиболее вероятное предположение. Пример: "Свет не включился, вероятно, датчик движения не отправил сигнал".

Собрать данные. Этот этап целиком и полностью посвящен работе с логами. Необходимо собрать все релевантные записи из всех источников за период времени, когда произошел инцидент.

Проанализировать данные. Собранные логи сравниваются с гипотезой. Подтверждается она или опровергается? Ищутся аномалии, ошибки, отклонения от штатного поведения. Если гипотеза опровергнута, выдвигается новая.

Сделать вывод и устранить причину. Как только первопричина найдена, вносятся изменения в логику сценария, конфигурацию устройства или систему в целом для ее устранения и предотвращения повторения инцидента.

Этот итеративный процесс позволяет систематически, шаг за шагом, добираться до корня проблемы, вместо хаотичных попыток "починить" то, что кажется сломанным.

---

Шаг 1: Восстановление хронологии событий

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

Основной инструмент для этой задачи — фильтрация логов по временному диапазону. Если пользователь сообщает, что сценарий "Доброе утро" не сработал сегодня в 7:00, бессмысленно изучать логи за весь день. Необходимо сузить область поиска до небольшого окна вокруг момента сбоя, например, с 6:55 по 7:05.

Для успешного восстановления хронологии необходимо агрегировать данные из нескольких источников:

• Логи Node-RED: Записываются в системный журнал Linux и содержат информацию о запуске потоков, ошибках в узлах `Function`, сообщения из узлов `Debug`.
• Журнал аудита (Audit Log): Ваша кастомная таблица в MySQL, куда, как мы рассматривали ранее, складываются все ключевые бизнес-события: срабатывание сценариев, изменение режимов, отправка команд на устройства.
• Логи MQTT-брокера: Позволяют увидеть, было ли вообще опубликовано сообщение от датчика или получена команда от интерфейса.
• Системные логи Linux (syslog/journald): Содержат информацию о работе самой операционной системы, сетевых интерфейсов, USB-устройств.

> 💡 Подсказка: Используйте команду `journalctl` в терминале Linux-контроллера HI для быстрого анализа системных логов, куда по умолчанию пишет и Node-RED. Основные флаги для фильтрации по времени: `--since` и `--until`.

# Пример: ищем все логи Node-RED в диапазоне 5 минут до и после сбоя в 7:00
journalctl -u nodered.service --since "2023-10-27 06:55:00" --until "2023-10-27 07:05:00"

Критически важным условием для корректной хронологии является синхронизация времени на всех компонентах системы с помощью протокола NTP (Network Time Protocol). Если время на контроллере, Zigbee-шлюзе и сервере базы данных будет отличаться хотя бы на несколько секунд, выстроить правильную причинно-следственную связь будет невозможно. Убедитесь, что NTP-клиент настроен и активен на всех устройствах вашей инфраструктуры.

Практический пример: Сбой сценария "Доброе утро"

Симптом: Пользователь жалуется, что в 7:00 не включился свет в спальне и не начал играть плейлист. Действия:

Подключаемся к контроллеру по SSH.

Выполняем команду для просмотра логов Node-RED в интересующем нас временном окне:

    journalctl -u nodered.service --since "today 06:55" --until "today 07:05"

    

Изучаем вывод. Ожидаемый лог "здоровой" системы:

    Oct 27 07:00:01 hi-controller Node-RED[1234]: [info] [inject:Сценарий "Доброе утро"]- Injecting message

    Oct 27 07:00:01 hi-controller Node-RED[1234]: [audit] [function:Лог начала сценария] - {"event": "scenario_start", "name": "good_morning", "source": "scheduler", "ts": 1698379201000}
    Oct 27 07:00:02 hi-controller Node-RED[1234]: [audit] [mqtt out:Свет в спальне] - Publishing command ON to topic 'devices/bedroom/light/set'
    Oct 27 07:00:03 hi-controller Node-RED[1234]: [audit] [http request:Запуск плейлиста] - Sending command to Sonos API
    ...
    

Анализ реального лога: В нашем логе мы видим, что в 7:00:00 нет записи от узла `inject`. Первая запись, связанная с этим потоком, появляется в 7:00:35 и гласит: `[error] [http request:Прогноз погоды] - Error: Request timed out after 30000ms`.

Первичный вывод: Узел `inject` сработал, но дальнейшее выполнение потока было заблокировано на 30 секунд из-за таймаута при обращении к погодному API. К тому моменту, как поток "отвис", время, релевантное для сценария, уже прошло, и пользователь заметил сбой. Первопричина — ненадёжный внешний API, блокирующий выполнение критичного по времени потока.

---

Шаг 2: Корреляция событий и поиск аномалий

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

Этот процесс называется корреляцией логов. Вы ищете связи между, на первый взгляд, разрозненными записями.

Отделите "норму" от "аномалии". Как мы обсуждали в уроке про "контракт" логирования, у вас должно быть четкое представление, как выглядит лог штатной работы. Любая запись, которая не соответствует этому шаблону, является кандидатом на аномалию. Например, если лог команды на включение света всегда содержит JSON `{ "command": "ON", "brightness": 100 }`, а вы видите запись `{"command": 1}`, — это аномалия.

Целенаправленно ищите ошибки. Начните поиск с записей, имеющих уровни `Warning`, `Error` и `Critical`. Это самый быстрый способ найти точки отказа. Используйте утилиту `grep` для фильтрации вывода `journalctl` или содержимого лог-файлов.

    # Показать только строки, содержащие "error" или "warn"

    journalctl -u nodered.service --since "06:55" --until "07:05" | grep -i -E "error|warn"
    

Анализируйте типичные паттерны ошибок. С опытом вы начнете узнавать "в лицо" наиболее частые проблемы:

* Таймауты (Timeout): Сообщения вида `Error: Request timed out`, `Modbus-Read: Timed out`, `No response from device`. Указывают на проблемы с сетью, недоступность внешнего сервиса или "зависшее" конечное устройство.

* Некорректный формат `msg.payload`: Ошибки вида `TypeError: Cannot read property 'value' of undefined`. Возникают, когда один узел передает `msg` в структуре, которую не ожидает следующий узел. Это классическое нарушение "контракта сообщения".

* Потеря связи с устройством: Записи `MQTT client disconnected`, `Modbus-Client: Serial port closed`. Указывают на физические проблемы: обрыв кабеля RS-485, сбой в работе Wi-Fi у устройства, перезагрузка MQTT-брокера.

* Ошибки `EHOSTUNREACH` или `ECONNRESET`: Стандартные сетевые ошибки TCP/IP, говорящие о недоступности хоста или разрыве соединения.

Задача корреляции — связать эти ошибки с наблюдаемым симптомом. Например, ошибка `Modbus-Read: Timed out` при опросе счетчика электроэнергии, за которой следует `TypeError: Cannot read property 'power' of undefined` в узле, рисующем график потребления, и как итог — пустой график на панели пользователя. Причина и следствие становятся очевидны.

---

Практический кейс: "Свет не включился по датчику движения"

Рассмотрим один из самых частых инцидентов и разберем его по шагам, используя нашу методологию.

• Симптом: Пользователь сообщает: "Вечером зашел в гардеробную, а свет не включился. Раньше всегда работал".
• Время: Примерно в 21:15.
• Гипотеза №1: Датчик движения (в нашем случае, Zigbee) не зафиксировал движение и не отправил сигнал.

Шаг 1: Проверка источника сигнала (Датчик и Шлюз)

Мы начинаем "раскручивать" цепочку с самого начала. Сигнал рождается на датчике, передается на шлюз (например, Zigbee2MQTT), а оттуда — в MQTT-брокер.

Смотрим логи Zigbee2MQTT (если они доступны, обычно через `journalctl -u zigbee2mqtt.service`). Ищем записи, связанные с нашим датчиком `motion_sensor_wardrobe` в районе 21:15.

Если в логах шлюза тишина, проблема, скорее всего, в самом датчике (села батарейка, вышел из строя). Гипотеза подтверждается.

Если же мы видим запись, это уже интереснее:

    info  2023-10-27 21:15:22: MQTT publish: topic 'zigbee2mqtt/motion_sensor_wardrobe', payload '{"motion": true, "linkquality": 98}'

    

Эта запись опровергает гипотезу №1. Сигнал от датчика был! Шлюз его получил и отправил в MQTT. Значит, проблема где-то дальше.

Шаг 2: Проверка в Node-RED

• Гипотеза №2: Сообщение от датчика не дошло до Node-RED или было обработано неверно.

> ⚠️ Внимание: Всегда проверяйте `msg.payload`! После обновлений прошивок устройств или узлов Node-RED формат данных может измениться. Явное логирование полученного `msg` в начале потока — лучшая практика, как мы рассматривали в уроке COURSE-07-M08-L07 по отладке.

Включаем узел `Debug`, подключенный сразу после узла `mqtt in`, который слушает топик `zigbee2mqtt/motion_sensor_wardrobe`. Просим пользователя еще раз зайти в гардеробную.

Смотрим на панель отладки в Node-RED и видим пришедшее сообщение:

    {

      "topic": "zigbee2mqtt/motion_sensor_wardrobe",
      "payload": {
        "motion": true,
        "linkquality": 98
      },
      "_msgid": "..."
    }
    

Теперь смотрим на логику нашего потока. Узел `switch`, который стоит дальше, проверяет условие: `msg.payload.occupancy` == `true`.

Эврика! Мы нашли несоответствие. Старая версия прошивки датчика или шлюза отправляла `{"occupancy": true}`, а новая, после недавнего обновления, стала отправлять `{"motion": true}`. Это классический пример нарушения неявного контракта. Наш поток ожидал одно поле в JSON, а получил другое.

Шаг 3: Проверка исполнительного устройства

Для полноты картины представим, что в Шаге 2 мы не нашли проблемы, и `msg.payload` был корректным.

• Гипотеза №3: Node-RED отправил команду на включение света, но исполнительное устройство (реле в контроллере) её не выполнило.

Мы смотрим в наш журнал аудита в MySQL. Есть ли там запись об отправке команды на включение `Relay-08` (свет в гардеробной) в 21:15?

Если записи нет, значит, проблема все же в логике Node-RED — поток по какой-то причине не дошел до узла, отправляющего команду.

Если запись есть, это означает, что Node-RED свою часть работы выполнил. Проблема глубже — на уровне аппаратного взаимодействия. Возможно, реле вышло из строя, или в момент отправки команды была кратковременная перегрузка шины контроллера. Здесь уже нужно смотреть на физическое состояние реле и его индикаторов.

Итоговый вывод по нашему кейсу: Первопричиной инцидента "свет не включился" стало изменение формата `msg.payload` от Zigbee-датчика после обновления. Решение — изменить настройку узла `switch` в Node-RED, чтобы он проверял поле `msg.payload.motion` вместо `msg.payload.occupancy`.

---

Шаг 3: Работа с системными логами Linux

Иногда проблема лежит за пределами логики Node-RED. Сам процесс Node-RED может работать нестабильно, падать или терять доступ к оборудованию. В этих случаях необходимо спуститься на уровень ниже — в логи операционной системы Linux Debian, на которой работает контроллер HI.

Основные инструменты здесь — утилиты командной строки `journalctl` (для современных систем с `systemd`) и просмотр файлов в директории `/var/log/`.

Когда нужно обращаться к системным логам:

• Процесс Node-RED не отвечает или постоянно перезапускается.
• Перестали работать все устройства на одной шине (например, все датчики на USB-RS485 адаптере).
• Контроллер перестал быть доступен по сети.
• Не хватает ресурсов (память, процессор), что приводит к общей "заторможенности" системы.

Практические команды и что в них искать

Отслеживание логов конкретной службы в реальном времени:

Команда `journalctl -u -f` позволяет "прицепиться" к потоку логов от нужного сервиса. Это бесценно для отладки.

    # Показывает новые сообщения от Node-RED по мере их появления

    journalctl -u nodered.service -f
    

Если вы видите, что сервис постоянно перезапускается (появляются сообщения `Started Node-RED`, а затем `Stopped Node-RED`), это явный признак критической ошибки при запуске.

Поиск проблем с оборудованием и ядром (dmesg):

Утилита `dmesg` выводит сообщения ядра Linux. Они содержат информацию о подключении и отключении USB-устройств, ошибках драйверов и т.д.

    # Ищем сообщения об ошибках, особенно связанных с USB или сетью

    dmesg | grep -i -E "error|fail|warn"
    

Если вы увидите здесь строку `usb 1-1.2: device descriptor read/64, error -110` или `ttyUSB0 disconnected`, это прямое указание на физическую проблему с USB-адаптером или его питанием.

Анализ общего системного журнала (syslog):

Файл `/var/log/syslog` (или его аналоги) является "свалкой" логов от множества системных служб.

    # Ищем записи о нехватке памяти. OOM Killer - процесс ядра, "убивающий"

    # приложения для освобождения памяти. Если он убил Node-RED, это и есть причина.
    grep -i "oom-killer" /var/log/syslog

    # Ищем общие предупреждения, которые могут навести на мысль о проблеме
    grep -i "warning" /var/log/syslog
    

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

---

Итоги: Формирование "базы знаний" инцидентов

Разбор инцидента не заканчивается на его устранении. Самый ценный актив, который вы получаете после успешного решения проблемы, — это знание. Если это знание не задокументировать, оно останется только в вашей голове и будет утеряно. При следующем аналогичном сбое вам или вашему коллеге придется проходить весь путь расследования с нуля.

> 🔗 Связанный материал: Структурированный подход к логированию (урок COURSE-07-M08-L05) и централизованное хранение логов (урок COURSE-07-M08-L06) являются фундаментом, на котором строится не только эффективный разбор инцидентов, но и последующее создание базы знаний.

Профессиональный подход — это создание базы знаний инцидентов. Это может быть простая страница в корпоративной Wiki или даже общий документ, куда заносится информация о каждом значимом сбое.

Шаблон отчета об инциденте

Каждая запись в базе знаний должна иметь четкую структуру.

• Инцидент ID: `INCIDENT-20231027-001`
• Симптом: Свет в гардеробной не включается по датчику движения.
• Время обнаружения: 27.10.2023, 21:15.
• Ключевые фрагменты логов:

    Лог Zigbee2MQTT:
    info: MQTT publish: topic 'zigbee2mqtt/motion_sensor_wardrobe', payload '{"motion": true, ...}'
    Логика в Node-RED:
    Узел Switch проверял msg.payload.occupancy.
    

• Диагностические шаги:

1. Проверили логи Z2M, убедились, что сигнал доходит до MQTT.

2. Подключили Debug в Node-RED, увидели расхождение в payload.

• Первопричина: Изменение формата данных (`motion` вместо `occupancy`) в сообщении от датчика после обновления прошивки Zigbee-шлюза.
• Решение: Изменен узел `Switch` в потоке `FLOW-AUTO-LIGHT-018` для проверки поля `motion`.
• Меры по предотвращению: Добавить в регламент тестирования после обновлений проверку ключевых форматов сообщений от устройств. Рассмотреть внедрение валидации JSON Schema на входе потоков.

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

Что дальше

В этом уроке мы научились "читать" следы, которые оставляет система, чтобы реконструировать события и находить первопричины сбоев. Мы прошли путь от жалобы пользователя до конкретной строчки в коде или логе. В следующем уроке мы перейдем от реактивного подхода (реагирование на уже случившийся сбой) к проактивному: научимся создавать системы мониторинга, которые будут предупреждать нас о потенциальных проблемах еще до того, как их заметит пользователь.