Журналирование (audit log) для отслеживания команд
Введение в журналирование: Зачем нужен аудит команд?
В процессе пусконаладки и эксплуатации систем автоматизации инженеры часто сталкиваются с ситуациями, когда поведение системы отклоняется от ожидаемого. Сработал ли сценарий? Была ли отправлена команда на исполнительное устройство? Почему не включился свет, хотя команда была отправлена? Ответы на эти вопросы часто ищут с помощью узла `Debug` в Node-RED, но это инструмент для моментальной, "живой" отладки. Он не предназначен для решения системных проблем. Здесь на сцену выходит журналирование — процесс систематической и постоянной записи ключевых событий системы.
> ℹ️ Информация: Отладка (`Debug` node) — это просмотр событий в реальном времени. Журналирование (logging) — это создание постоянной, хронологической записи для последующего анализа.
Журнал аудита команд (или аудиторский журнал, audit log) — это специализированный тип журнала, который фокусируется на отслеживании жизненного цикла команд, управляющих физическими устройствами. Он фиксирует не все подряд, а только значимые с точки зрения бизнес-логики события: отправка команды, получение подтверждения, срабатывание таймаута, повторная попытка, возникновение ошибки.Узел `Debug` имеет ряд фундаментальных ограничений, которые делают его непригодным для серьезного анализа инцидентов:
- Эфемерность: Данные в окне отладки исчезают при перезагрузке контроллера или обновлении страницы браузера. Они не сохраняются на постоянной основе.
- Неструктурированность: Вывод `Debug` может быть хаотичным потоком разнородных данных, что затрудняет поиск связанной информации.
- Производительность: Активное использование `Debug` в сложных системах может создавать ощутимую нагрузку на контроллер и канал связи с браузером. В промышленных инсталляциях (`production mode`) его часто отключают полностью.
Цели внедрения аудиторского журнала команд:
Важно отличать прикладной журнал аудита команд от системных логов. Системный журнал (syslog) контроллера HI содержит информацию от операционной системы Linux и сервисов (запуск Node-RED, сетевые ошибки, проблемы с драйверами). Журнал аудита создается нами внутри Node-RED и содержит события из логики наших сценариев автоматизации. Это два разных, но одинаково важных инструмента диагностики.
---
Проектирование структуры лога: Какие данные сохранять?
Чтобы журнал был полезным инструментом, а не просто свалкой данных, каждое событие должно быть записано в едином, структурированном формате. Лучшим выбором для этого является JSON, поскольку его легко парсить и анализировать как человеком, так и машиной.
Принцип создания информативного лог-сообщения — оно должно самодостаточно отвечать на вопросы: "Когда?", "Что?", "С кем/чем?" и "Насколько критично?".
Обязательные поля для аудита команд
Каждая запись в нашем `audit.log` будет представлять собой JSON-объект со следующим набором полей:
| Поле | Тип | Описание | Пример |
| ------------------ | --------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | --------------------------------------------- |
| `ts` (timestamp) | Number | Временная метка события в формате Unix epoch (миллисекунды). Позволяет точно восстановить хронологию. | `1678886400123` |
| `level` | String | Уровень важности события. Позволяет быстро фильтровать логи. Стандартные уровни: `INFO`, `WARN` (Warning), `ERROR`. | `"INFO"` |
| `event` | String | Тип события. Описывает, что именно произошло. | `"CMD_SENT"`, `"ACK_OK"`, `"TIMEOUT_ERROR"` |
| `actor_id` | String | Уникальный идентификатор "актора" — устройства или сценария, с которым связано событие. Это может быть ID реле, ID датчика, ID сценария. | `"light-kitchen-main"` |
| `correlation_id` | String | Ключевое поле! Уникальный идентификатор, связывающий все события одной транзакции. Генерируется один раз при инициации команды. | `"tx-a8b4-c1d9-e2f3"` |
| `message` | String | Человекочитаемое описание события. | `"Command ON sent to relay"` |
| `payload` | Object/Any| Оригинальные данные, связанные с событием. Это может быть команда, которую отправили, или полученный ответ. Помогает в детальном анализе. | `{"command": "ON", "value": true}` |
Важность `correlation_id`
Представьте, что вы одновременно отправляете команды на включение света на кухне и в спальне. В логе появится два события `CMD_SENT`, затем, возможно, два `ACK_OK`. Как понять, какое подтверждение относится к какой команде?
Идентификатор корреляции (`correlation_id`) решает эту проблему. Это уникальная строка (например, UUID), которая генерируется в самом начале сценария (при получении триггера на действие) и "приклеивается" ко всем последующим сообщениям (`msg`) внутри этой транзакции.Когда мы смотрим в лог, мы можем отфильтровать все записи по одному `correlation_id` и увидеть всю историю одной операции:
Если же подтверждение не пришло, мы увидим:
Таким образом, `correlation_id` превращает разрозненные записи в связанную историю транзакции.
Пример готового лог-сообщения в формате JSON:
{
"ts": 1678886400123,
"level": "INFO",
"event": "CMD_SENT",
"actor_id": "light-kitchen-main",
"correlation_id": "tx-a8b4-c1d9-e2f3",
"message": "Send command ON to relay module, output RL-05",
"payload": {
"value": true
}
}
---
Реализация логгера в Node-RED: Пишем в файл
Теперь давайте создадим механизм, который будет принимать сообщения и записывать их в файл в нашем стандартизированном JSON-формате. Чтобы не дублировать эту логику во всех потоках, мы создадим переиспользуемый компонент — подпрограмму (subflow).
Создание Subflow "Audit Logger"
`[Input]` -> `[Function: Format Log]` -> `[File: Append to audit.log]`
Это будет наш универсальный логгер. Любое сообщение, поданное на его вход, будет отформатировано и записано в файл.
Конфигурация узлов внутри Subflow
1. Узел `Function: Format Log`
Этот узел — сердце нашего логгера. Он принимает на вход `msg` от любого сценария и формирует из него стандартизированный JSON-объект для записи в лог.
Код для узла `Function`:// Ожидается, что на вход придет msg, содержащий объект msg.log_data
// msg.log_data = {
// level: "INFO",
// event: "CMD_SENT",
// actor_id: "my-device-id",
// message: "Human-readable message",
// payload: { ... }
// };
// Также ожидается, что msg.correlation_id уже существует.
// 1. Проверяем наличие обязательных данных
if (!msg.log_data || !msg.log_data.event) {
node.warn("Log data is missing or incomplete. Logging aborted.");
return null; // Не передаем сообщение дальше
}
// 2. Создаем финальный объект для лога
const logEntry = {
ts: Date.now(),
level: msg.log_data.level || "INFO", // Уровень INFO по умолчанию
event: msg.log_data.event,
actor_id: msg.log_data.actor_id || "unknown",
correlation_id: msg.correlation_id || "not_set",
message: msg.log_data.message || "",
payload: msg.log_data.payload || {}
};
// 3. Преобразуем объект в строку JSON и добавляем перенос строки
msg.payload = JSON.stringify(logEntry) + "\n";
return msg;
Этот код стандартизирует запись и делает ее предсказуемой. Он также выполняет базовую валидацию, чтобы в лог не попал "мусор".
2. Узел `File: Append to audit.log`
Этот узел отвечает за физическую запись данных на диск контроллера.
Настройки узла `file`:- Filename: Укажите полный путь к файлу лога. Для контроллера HI на базе Debian рекомендуется использовать стандартный каталог для логов: `/var/log/hi-controller/audit.log`.
- Action: Выберите `append to file` (дописывать в файл).
- Add newline (`\n`) to each payload? — снимите эту галочку, так как мы уже добавили `\n` в узле `Function`.
- Create directory if it doesn't exist? — установите эту галочку.
> ⚠️ Внимание: Простое добавление в файл может быстро исчерпать место на диске контроллера. В промышленных инсталляциях абсолютно необходимо настроить ротацию логов (log rotation). Для этого используется стандартная утилита Linux `logrotate`, которая периодически архивирует и удаляет старые файлы логов. Ее настройка выходит за рамки данного урока, но является обязательным шагом для сдачи объекта в эксплуатацию.
Теперь у нас есть готовый `Subflow: Audit Logger`. Мы можем использовать его в любом потоке, просто добавив соответствующий узел из палитры и подав на него `msg`, содержащий `msg.log_data` и `msg.correlation_id`.
---
Практика: Интеграция логгера в паттерн Ack/Timeout
Давайте вернемся к потоку управления исполнительным устройством с подтверждением и таймаутом, который мы создали в предыдущем уроке (`COURSE-05-M04-L04`). Сейчас мы добавим в него точки журналирования, чтобы отслеживать каждый шаг операции.
> 💡 Подсказка: Используйте осмысленные имена для узлов `link`, например: `LOG:CMD_SENT` или `LOG:TIMEOUT`. Это делает поток самодокументируемым и значительно упрощает его чтение.
Модифицированная схема потока://========= Исходный триггер и генерация Correlation ID ===========
[Inject: Start] --> [Function: Gen CorrID] --+
|
//========= Основная логика: Команда -> Таймаут -> Повтор =========
|
+--------------------------------------------+
| |
| [Change: Set Cmd] -> [Link Out: LOG CMD] | // 1. Логируем отправку
| | |
| v |
| [Relay Out] -> [Trigger: Timeout]---------+--> [Link Out: LOG TIMEOUT] // 3. Логируем таймаут
| | |
| (output 1) |
| v |
| [Function: Reset] | // Успешно, сброс таймаута
| |
//========= Обработка подтверждения (Ack) ========
| |
| [MQTT In: Ack] --> [Function: Validate Ack] |
| | (valid) |
| |--------------------+--> [Link Out: LOG ACK] // 2. Логируем подтверждение
| |
//=========== Централизованный логгер ===========
| |
+--> [Link In: Collect Logs] -> [Subflow: Audit Logger]
Пошаговая интеграция
// Node: Generate Correlation ID
msg.correlation_id = "tx-" + Date.now() + "-" + Math.random().toString(16).substr(2, 8);
return msg;
После отправки команды: Сразу после узла, формирующего команду, и перед* узлом `Relay Out`, вставьте узел `Change` или `Function`, который готовит `msg.log_data`, и отправьте его на `link out` с именем `LOG EVENT`.
// Node: Prepare CMD_SENT log
msg.log_data = {
level: "INFO",
event: "CMD_SENT",
actor_id: "light-kitchen-main",
message: "Command " + msg.payload + " sent to relay.",
payload: msg.payload
};
return msg;
* При получении подтверждения (Ack): После узла валидации `Ack`, в ветке успешного подтверждения, добавьте узел для формирования `log_data` с `event: "ACK_OK"` и отправьте его на тот же `link out: LOG EVENT`.
* При срабатывании таймаута: На выходе узла `Trigger`, который сигнализирует о таймауте, добавьте узел для формирования `log_data` с `level: "WARN"` и `event: "TIMEOUT_ERROR"`. Отправьте его на `link out: LOG EVENT`.
Анализ итогового файла `audit.log`
После выполнения сценария откроем файл `/var/log/hi-controller/audit.log`. Мы увидим там что-то вроде этого:
{"ts":1678887100305,"level":"INFO","event":"CMD_SENT","actor_id":"light-kitchen-main","correlation_id":"tx-1678887100304-a1b2c3d4","message":"Command true sent to relay.","payload":true}
{"ts":1678887100451,"level":"INFO","event":"ACK_OK","actor_id":"light-kitchen-main","correlation_id":"tx-1678887100304-a1b2c3d4","message":"Acknowledge received successfully.","payload":{"status":"OK"}}
А в случае сбоя и повтора:
{"ts":1678887200100,"level":"INFO","event":"CMD_SENT","actor_id":"socket-livingroom-tv","correlation_id":"tx-1678887200099-e5f6g7h8","message":"Command true sent to relay.","payload":true}
{"ts":1678887205105,"level":"WARN","event":"TIMEOUT_ERROR","actor_id":"socket-livingroom-tv","correlation_id":"tx-1678887200099-e5f6g7h8","message":"Acknowledge timeout after 5 seconds","payload":{}}
{"ts":1678887205108,"level":"INFO","event":"RETRY_SENT","actor_id":"socket-livingroom-tv","correlation_id":"tx-1678887200099-e5f6g7h8","message":"Retry 1: Command true sent to relay.","payload":true}
{"ts":1678887205250,"level":"INFO","event":"ACK_OK","actor_id":"socket-livingroom-tv","correlation_id":"tx-1678887200099-e5f6g7h8","message":"Acknowledge received successfully.","payload":{"status":"OK"}}
Благодаря `correlation_id` мы четко видим всю историю одной операции, даже если она была прервана, и можем легко найти все связанные события.
---
Итоги и базовый анализ логов
В этом уроке мы сделали гигантский шаг от простой отладки к профессиональному подходу в мониторинге систем автоматизации. Мы спроектировали и реализовали персистентный, структурированный аудиторский журнал, который позволяет отслеживать жизненный цикл каждой важной команды, отправляемой в системе.
Этот журнал становится вашим "единственным источником правды" при разборе инцидентов. Он позволяет объективно отвечать на вопросы о работе системы, опираясь на факты, а не догадки.
Для анализа логов непосредственно на контроллере HI можно использовать мощные инструменты командной строки Linux:
- Просмотр в реальном времени: Команда `tail -f` позволяет видеть новые записи в логе по мере их появления. Это как `Debug` нода, но для файла.
tail -f /var/log/hi-controller/audit.log
- Поиск по ключевому слову: Утилита `grep` позволяет отфильтровать строки, содержащие нужную информацию, например, все ошибки или все события для конкретного устройства.
# Найти все ошибки
grep '"level":"ERROR"' /var/log/hi-controller/audit.log
# Найти все события для устройства 'light-kitchen-main'
grep 'light-kitchen-main' /var/log/hi-controller/audit.log
- Работа с JSON: Утилита `jq` — это "sed/awk для JSON". Она позволяет красиво форматировать, фильтровать и извлекать данные из JSON-логов.
# Показать все логи с уровнем WARN в отформатированном виде
cat /var/log/hi-controller/audit.log | jq 'select(.level == "WARN")'
# Найти все события по одному correlation_id
cat /var/log/hi-controller/audit.log | jq 'select(.correlation_id == "tx-1678887200099-e5f6g7h8")'
Что дальше?
Локальный файл с логами — отличное начало. Для крупных объектов, состоящих из нескольких контроллеров, следующим шагом является внедрение централизованной системы сбора и анализа логов. Такие системы, как стек ELK (Elasticsearch, Logstash, Kibana) или Grafana Loki, позволяют агрегировать логи со всех устройств в одном месте, строить по ним графики, настраивать дашборды и сложные правила оповещения. Созданная нами структурированная модель лога идеально подходит для интеграции с такими системами.
В следующем модуле мы рассмотрим продвинутые сценарии взаимодействия между устройствами и научимся создавать сложные логические цепочки.