Практика: Анализ логов для поиска ошибки в сценарии

Урок 7 · Сценарии умного дома: режимы, состояния, приоритеты · 30 мин · theory

Введение: Постановка задачи для отладки

> ℹ️ Информация: Четко сформулированная проблема — половина решения. Прежде чем погружаться в логи, всегда зафиксируйте, что именно и при каких условиях работает не так, как ожидалось.

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

Описание сценария "Возвращение домой"

Сценарий разработан для повышения комфорта пользователя при прибытии в квартиру или дом.

Триггер: Система определения присутствия (например, Unifi Wi-Fi Controller) публикует в MQTT-топик `presence/users/alice` сообщение `{"status": "online"}` как только смартфон пользователя `alice` подключается к домашней Wi-Fi сети. Ожидаемое поведение (при выполнении следующих условий):

Текущее время — вечернее (после 18:00).

Общий режим дома — "Отсутствие" (`home/mode` = "away").

Освещение в прихожей выключено.

Последовательность действий:

Контроллер HI, получив MQTT-сообщение, переводит общий режим дома в "Присутствие" (`home/mode` = "present").

Система отправляет команду на DALI-шлюз для плавного включения света в прихожей (группа `G01`) до уровня 70% в течение 3 секунд.

В журнал событий (MySQL) записывается информационное сообщение: `Сценарий "Возвращение домой" для пользователя alice выполнен успешно.`

Фактическое (некорректное) поведение

Владелец объекта сообщает о проблеме: "Когда я возвращаюсь домой вечером, свет в прихожей иногда включается и тут же гаснет. Иногда не включается совсем. Проблема проявляется не каждый раз, примерно в 3 случаях из 10."

Наблюдаемые симптомы:

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

Обзор задействованных компонентов

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

Система определения присутствия: Внешний сервис, подключенный к Wi-Fi роутеру. Является источником триггера. Нам важно знать, что он публикует сообщения в MQTT.
MQTT-брокер: Промежуточное звено, передающее сообщение от системы присутствия к контроллеру HI. Работает на самом контроллере.
Контроллер HI (Node-RED): Ядро логики. Здесь расположен поток (flow), который обрабатывает триггер и принимает решения.
DALI-шлюз: Устройство, подключенное к контроллеру (например, по шине CAN или TCP/IP) и управляющее светильниками по протоколу DALI.
База данных MySQL: Место, где хранятся персистентные логи (журнал событий), как было рассмотрено в уроке `COURSE-07-M04-L02`.

Постановка задачи ясна: у нас есть нестабильно работающий сценарий. Наша цель — используя доступные инструменты отладки, найти и устранить первопричину сбоя.

---

Шаг 1: Первичная диагностика с помощью узла Debug

Первая линия обороны инженера-автоматизатора — узел `Debug`. Его задача — показать нам "живой" поток сообщений (`msg`) внутри Node-RED. Наша стратегия — расставить `Debug`-узлы в ключевых точках потока, чтобы увидеть, где ожидаемый поток данных прерывается или искажается.

> 💡 Подсказка: Называйте узлы Debug осмысленно (например, 'После проверки времени', 'Перед командой на DALI'), чтобы легко идентифицировать источник сообщения в логах боковой панели.

Стратегическое размещение узлов Debug

Представим упрощенную структуру нашего потока `FLOW-AUTO-WELCOME-001`:

[MQTT In] -> [Switch: check user 'alice'] -> [Function: "Проверка условий"] -> [DALI Command] -> [Logger]

Мы разместим `Debug`-узлы в следующих точках:

Сразу после `MQTT In`: Назвем его `[Debug] Входной триггер MQTT`. Цель — увидеть, какое именно сообщение приходит от системы присутствия в первозданном виде.

После узла `Function: "Проверка условий"`: Назвем `[Debug] Результат проверки`. Цель — проверить, правильно ли узел оценивает время суток и текущий режим дома.

Перед узлом `DALI Command`: Назвем `[Debug] Команда на DALI`. Цель — убедиться, что формируется корректная команда для шлюза освещения.

Обновленная схема потока с узлами отладки:

             +-> [Debug] Входной триггер MQTT
             |
[MQTT In] ---+-> [Switch: check user 'alice'] -> [Function: "Проверка условий"] --+--> [Debug] Результат проверки
                                                                                  |
                                                                                  +--> [DALI Command] --> [Logger]
                                                                                        ^
                                                                                        |
                                                                                  [Debug] Команда на DALI

Примечание: узлы `Debug` подключаются параллельно основному потоку, чтобы не прерывать его работу.

Анализ сообщений в панели отладки

Теперь мы просим пользователя воспроизвести ситуацию (вернуться домой) или имитируем ее сами, отправив тестовое MQTT-сообщение.

Сценарий 1: Успешное выполнение

Мы видим в панели отладки последовательность сообщений:

// Сообщение от "[Debug] Входной триггер MQTT"
{
  "topic": "presence/users/alice",
  "payload": {
    "status": "online",
    "device_mac": "AA:BB:CC:11:22:33"
  },
  "_msgid": "..."
}

// Сообщение от "[Debug] Результат проверки"
// Узел Function добавил данные о проверках
{
  "topic": "presence/users/alice",
  "payload": {
    "status": "online",
    "device_mac": "AA:BB:CC:11:22:33"
  },
  "conditions": {
    "isTimeOK": true,
    "isModeAway": true
  },
  "action": "turn_on_light",
  "_msgid": "..."
}

// Сообщение от "[Debug] Команда на DALI"
// Узел DALI ожидает payload в виде команды
{
  "payload": {
    "command": "SET_LEVEL",
    "group": "G01",
    "value": 70,
    "fade_time": 3
  },
  "_msgid": "..."
}

Эта последовательность полностью соответствует нашим ожиданиям. Свет включился.

Сценарий 2: Неудачное выполнение

После нескольких попыток мы наконец "ловим" момент сбоя. В панели отладки мы видим только одно сообщение:

// Сообщение от "[Debug] Входной триггер MQTT"
{
  "topic": "presence/users/alice",
  "payload": "online",
  "_msgid": "..."
}

Сообщений от `[Debug] Результат проверки` и `[Debug] Команда на DALI` нет! Это критически важная улика. Она говорит нам, что поток прервался где-то между `MQTT In` и выходом из узла `Function: "Проверка условий"`.

Первоначальная гипотеза: структура `msg.payload` нестабильна. Иногда система присутствия присылает полный JSON-объект, а иногда — простую строку `"online"`. Наш узел `Function`, скорее всего, не готов к такому и при попытке обработать строку вместо объекта генерирует ошибку, молча прекращая выполнение потока.

Проблема узла `Debug` в том, что он не показывает ошибки, которые не были явно перехвачены. Он лишь показывает, что сообщение "не дошло". Для более глубокого анализа нам нужны персистентные логи.

---

Шаг 2: Глубокий анализ с использованием персистентных логов

Интерактивная отладка с помощью узла `Debug` хороша для поиска явных проблем. Но для "плавающих" ошибок, которые случаются редко и непредсказуемо, нам нужен ретроспективный анализ. Для этого мы будем использовать журнал событий, который, как было показано в предыдущих уроках, пишется в базу данных MySQL на контроллере HI.

> ⚠️ Внимание: Убедитесь, что время на контроллере HI синхронизировано по NTP. Рассинхронизация времени на несколько секунд делает корреляцию событий от разных источников практически невозможной.

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

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

Вспоминаем структуру нашей таблицы `audit_log` в MySQL:

| Поле | Тип | Описание |

|-----------|--------------|-------------------------------------------|

| `id` | INT AUTO_INC | Уникальный идентификатор записи |

| `ts` | TIMESTAMP | Временная метка события с точностью до мс |

| `level` | VARCHAR(10) | Уровень логирования (INFO, WARN, ERROR) |

| `source` | VARCHAR(100) | ID узла или сценария (например, `FLOW-AUTO-WELCOME-001`) |

| `message` | TEXT | Текстовое описание события |

| `details` | JSON | Детализированное сообщение `msg` в формате JSON |

Использование SQL-запросов для фильтрации

Мы знаем примерное время инцидента (вчера вечером) и задействованные компоненты. Этого достаточно, чтобы составить эффективный SQL-запрос для поиска улик. Подключимся к базе данных MySQL на контроллере через консоль или любой SQL-клиент.

Задача запроса: Выбрать все события, связанные со сценарием "Возвращение домой" и управлением освещением, за интересующий нас промежуток времени.

SELECT
    ts,
    level,
    source,
    message,
    JSON_EXTRACT(details, '$.payload') AS payload_details
FROM
    audit_log
WHERE
    ts BETWEEN 'YYYY-MM-DD HH:MM:SS' -- (укажите начало интересующего периода)
    AND 'YYYY-MM-DD HH:MM:SS' -- (укажите конец периода)
    AND (
        source LIKE 'FLOW-AUTO-WELCOME%'
        OR source LIKE 'dali_gateway%'
        OR message LIKE '%alice%'
    )
ORDER BY
    ts ASC;

Корреляция событий по временным меткам

Результат запроса может выглядеть так:

Примечание: Даты в таблице ниже приведены в качестве примера разбора реального инцидента.

|---------------------|-------|----------------------------|---------------------------------------------|------------------------------------|

| 2023-10-26 18:05:15 | INFO | FLOW-AUTO-WELCOME-001 | Входной триггер: presence/users/alice | `{"status": "online", "device_mac": "..."}` |

| 2023-10-26 18:05:15 | INFO | FLOW-AUTO-WELCOME-001 | Условия выполнены, запуск сценария | `{"action": "turn_on_light"}` |

| 2023-10-26 18:05:16 | INFO | dali_gateway_interface | Команда отправлена: G01, уровень 70% | `{"group": "G01", "value": 70}` |

| ... | ... | ... | ... | ... |

| 2023-10-26 18:32:41 | ERROR | system.node-red.catch | TypeError: Cannot read properties of null (reading 'status') | `{"error": {"source": {"id": "...", "type": "function", "name": "Проверка условий"}}}` |

Эта таблица — "черный ящик" нашего инцидента. Что мы видим:

В 18:05:15 произошел успешный запуск. `payload_details` был JSON-объектом. Все три этапа (триггер, проверка, команда) прошли штатно.

В 18:32:41 произошел сбой. `payload_details` был строкой. Сразу после триггера мы видим запись с уровнем `ERROR` и источником `system.node-red.catch`. Это сработал наш глобальный узел `Catch`, который мы настроили в уроке `COURSE-07-M04-L03`.

Сообщение об ошибке `TypeError: Cannot read properties of null (reading 'status')` и информация в `details` JSON (`source.name: "Проверка условий"`) однозначно указывают на проблемный узел.

Логи подтвердили нашу гипотезу: узел `Function` с именем "Проверка условий" "упал" при попытке прочитать свойство `status` у строки.

---

Шаг 3: Локализация и идентификация первопричины

Теперь, когда у нас есть точные координаты сбоя — узел `Function` с именем "Проверка условий" — мы можем перейти к анализу его кода. Нам больше не нужно гадать, мы точно знаем, где искать.

> 🔗 Связанный материал: Для более глубокого понимания обработки ошибок, обратитесь к уроку `COURSE-07-M04-L03`: Отладка в Node-RED: узлы Debug, Catch, Status.

Анализ кода проблемного узла

Открываем узел `Function: "Проверка условий"` и видим следующий код:

// Проблемный код
let status = msg.payload.status; // <--- Точка отказа

if (status === "online") {
    // ... дальнейшая логика проверки времени и режима дома

    // Получаем текущее состояние из контекста потока
    let isTimeOk = flow.get("isEvening") || false;
    let homeMode = flow.get("homeMode") || "unknown";

    if (isTimeOk && homeMode === "away") {
        node.status({ fill:"green", shape:"dot", text:"Условия выполнены" });
        return msg; // Передаем сообщение дальше
    }
}

node.status({ fill:"yellow", shape:"ring", text:"Условия не выполнены" });
return null; // Останавливаем поток, если условия не совпали

Анализ:

Код в первой строке (`let status = msg.payload.status;`) написан с допущением, что `msg.payload` — это всегда объект, имеющий свойство `status`.

Когда приходит `"payload": {"status": "online"}`, код работает: `msg.payload.status` возвращает `"online"`.
Когда приходит `"payload": "online"`, `msg.payload` является строкой. Попытка обратиться к свойству `status` у строки (`"online".status`) вернет `undefined`. В некоторых версиях JS это может привести к ошибке. Если бы было `msg.payload.status.toLowerCase()`, это была бы гарантированная ошибка `TypeError`. В нашем логе именно она (`Cannot read properties of null/undefined`). Javascript пытается прочитать свойство у примитива, что приводит к исключению (exception), которое прерывает выполнение всего кода в узле.

Сообщение не передается дальше по потоку и не возвращается `null`, оно просто "исчезает" вместе с необработанным исключением.

Использование узла Catch для анализа исключений

Именно для таких случаев и нужен узел `Catch`. Настроив его на перехват ошибок со всех узлов на вкладке, мы получаем бесценную информацию. Когда в узле `Function` происходит исключение, узел `Catch` генерирует новое сообщение `msg`, которое содержит:

`msg.error`: Объект с информацией об ошибке.
`msg.error.message`: Текстовое сообщение ошибки (`TypeError: ...`).
`msg.error.source`: Объект, описывающий узел-источник сбоя (его ID, тип и имя).

Пример `msg`, пойманного узлом `Catch`:

{
  "error": {
    "message": "TypeError: Cannot read properties of undefined (reading 'status')",
    "source": {
      "id": "a1b2c3d4.e5f6g7",
      "type": "function",
      "name": "Проверка условий",
      "count": 1
    },
    "stack": "TypeError: Cannot read properties of undefined (reading 'status')\n    at /data/node_modules/node-red/red/runtime/nodes/node-instance.js:327:27\n    ..."
  },
  "_msgid": "...",
  "payload": "online", // Оригинальный payload, вызвавший ошибку!
  "topic": "presence/users/alice"
}

Сохраняя этот объект в `details` нашей таблицы `audit_log`, мы получаем полную картину инцидента для последующего анализа, что мы и сделали на предыдущем шаге.

Итог локализации: Первопричина — недостаточно надежный (robust) код в узле `Function`, который не проверяет тип и структуру входящих данных перед их обработкой. Сценарий не учитывает вариативность данных от внешнего источника (системы определения присутствия).

---

Шаг 4: Исправление ошибки и верификация решения

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

> 💡 Подсказка: Используйте `node.status()` в исправленном коде, чтобы визуально отображать текущее состояние узла (например, 'Статус: Ожидание') прямо под ним в редакторе Node-RED. Это значительно улучшает наблюдаемость.

Написание устойчивого к ошибкам кода

Наша задача — модифицировать код в узле `Function: "Проверка условий"` так, чтобы он корректно обрабатывал `msg.payload` любого из двух форматов: как объект и как строку. Это называется "защитное программирование" (defensive programming).

Исправленный код в узле `Function`:

// 1. Извлекаем сырой payload
let payload = msg.payload;
let status = "";

// 2. Валидация и извлечение данных (Pattern "Контракт сообщения")
if (typeof payload === 'object' && payload !== null && payload.status) {
    // Обрабатываем случай, когда payload - это объект {"status": "online"}
    status = payload.status;
    node.log("Обработка payload как объекта.");
} else if (typeof payload === 'string') {
    // Обрабатываем случай, когда payload - это строка "online"
    status = payload;
    node.log("Обработка payload как строки.");
} else {
    // Если payload имеет неизвестный формат, логируем ошибку и останавливаем поток
    node.error("Неподдерживаемый формат payload: " + JSON.stringify(payload), msg);
    node.status({ fill: "red", shape: "dot", text: "Ошибка формата payload" });
    return null;
}

// 3. Основная логика сценария
if (status === "online") {
    // Получаем текущее состояние из контекста потока
    let isTimeOk = flow.get("isEvening") || false;
    let homeMode = flow.get("homeMode") || "unknown";

    if (isTimeOk && homeMode === "away") {
        node.status({ fill: "green", shape: "dot", text: "Условия выполнены, запуск" });
        // Сохраняем информацию для следующих узлов
        msg.action = "turn_on_light";
        msg.user = "alice";
        return msg; // Передаем сообщение дальше
    } else {
        node.status({ fill: "yellow", shape: "ring", text: "Условия не выполнены" });
        return null;
    }
}

// Если статус не "online", просто останавливаем поток
node.status({ fill: "grey", shape: "dot", text: "Статус не 'online'" });
return null;

Что мы изменили:

Добавили проверку типа: Теперь код сначала проверяет, чем является `payload` — объектом или строкой.

Унифицировали данные: Независимо от формата, мы извлекаем значение статуса в переменную `status`.

Добавили обработку ошибок: Если формат `payload` неизвестен, мы генерируем явную ошибку с помощью `node.error()` (которую поймает `Catch`) и безопасно останавливаем поток, возвращая `null`.

Улучшили визуальный статус: Добавлены вызовы `node.status()` для каждого возможного исхода, что позволяет мгновенно понять, что происходит внутри узла, просто взглянув на него в редакторе.

Процесс верификации

После внесения изменений и развертывания (Deploy) потока необходимо провести верификацию — доказать, что исправление работает и не привнесло новых ошибок.

Тест-кейс 1 (негативный): Имитация сбойного сообщения.

* Действие: С помощью узла `Inject` или MQTT-клиента отправляем в топик `presence/users/alice` сообщение с `payload` в виде строки: `"online"`.

* Ожидаемый результат: Свет в прихожей включается. В логах MySQL появляется запись об успешном выполнении. В статусе узла `Function` отображается "Условия выполнены, запуск".

* Проверка: Выполняем действие и наблюдаем за физическим результатом и логами. Результат соответствует ожиданиям.

Тест-кейс 2 (позитивный): Имитация штатного сообщения.

* Действие: Отправляем в тот же топик сообщение с `payload` в виде JSON-объекта: `{"status": "online", "device_mac": "..."}`.

* Ожидаемый результат: Аналогичен предыдущему пункту. Свет включается.

* Проверка: Выполняем. Результат соответствует ожиданиям.

Тест-кейс 3 (негативный, граничный): Имитация некорректного payload.

* Действие: Отправляем в топик сообщение с `payload` в виде числа: `123`.

* Ожидаемый результат: Свет не включается. В логах MySQL появляется запись об ошибке `ERROR` от нашего `Function`-узла с сообщением "Неподдерживаемый формат payload". Поток выполнения останавливается.

* Проверка: Выполняем. Результат соответствует ожиданиям.

Успешное прохождение всех тест-кейсов подтверждает, что ошибка исправлена, а надежность сценария повышена.

---

Итоги: Методология отладки в действии

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

Давайте закрепим пройденный четырехшаговый процесс:

Постановка задачи и Воспроизведение (Define & Reproduce): Мы четко определили, как система должна работать и как она работает на самом деле. Это позволило сфокусировать поиск.

Анализ и Гипотеза (Analyze & Hypothesize): С помощью узлов `Debug` мы провели первичную диагностику и выдвинули гипотезу о нестабильной структуре `msg.payload`. Затем, используя SQL-запросы к персистентным логам, мы подтвердили эту гипотезу, проанализировав исторические данные.

Изоляция и Идентификация (Isolate & Identify): Анализ логов из узла `Catch` позволил нам с хирургической точностью определить узел-источник и конкретную строку кода, вызывающую сбой. Мы локализовали проблему от целого сценария до одной строки.

Исправление и Верификация (Fix & Verify): Мы написали более надежный код, который учитывает различные форматы входных данных. После этого мы провели серию тестов, чтобы убедиться, что исправление работает и не вносит побочных эффектов.

Синергия инструментов

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

Узел `Debug`: Идеален для быстрой, интерактивной проверки "здоровья" потока в реальном времени.
Узел `Catch`: Незаменимая "страховочная сетка", которая ловит необработанные исключения и предотвращает "тихие" отказы, превращая их в документированные события.
Персистентные логи (MySQL): "Черный ящик" вашей системы, позволяющий проводить ретроспективный анализ, находить корреляции и расследовать "плавающие" ошибки постфактум.
Узел `Status`: Обеспечивает "наблюдаемость" (observability), позволяя вам визуально контролировать состояние потока без необходимости постоянно смотреть в панель отладки.

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

Что дальше

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