Свой логгер: уровни DEBUG/INFO/WARN и метки времени

Инкубатор на балконе я довёл до ума за две недели, а потом месяц не мог ответить на простой вопрос: что случилось в ночь на вторник. Скетч писал в порт всё подряд — каждая секунда приносила строку вида v=531 rele=0, за сутки набегало восемьдесят шесть тысяч строк. Утром, после поездки с перегревом, я листал журнал глазами и не находил момента, когда температура пошла вверх: сырой опрос датчика, обычная работа и настоящая тревога выглядели в нём одинаково, а времени в строках не было вовсе. Порядок событий приходилось восстанавливать по памяти, то есть никак.

Часть решения у нас уже есть. Уровневый логгер из урока про уровни логов расставил веса: метки [D], [I], [W], [E] и правило двойного подтверждения. Но он вырос в четыре отдельные функции-обёртки, и как только я завёл второй проект, форматы поплыли: в одном stamp() печатал секунды, в другом — HEX, в третьем метка уровня переехала в конец строки. DBG-макросы из урока про условную компиляцию вырезают печати при сборке, но не умеют разного веса внутри одной сборки: в бою нужен WARN, а не пустота.

Поэтому здесь один вход вместо четырёх: функция с уровнем-аргументом и макрос LOG(u, m) над ней. Метка millis() встаёт в начало строки сырым числом — интервалы между событиями считаются вычитанием прямо в мониторе. Порог живёт в одной константе POROG: на столе она равна нулю и видно всё, в боевой сборке — двойке, и до порта доехают только предупреждения. Отдельно разберём ловушку, на которой я обжёгся со зуммером на прерывании: Serial.print внутри обработчика стоит миллисекунды, логгеру там место только в виде флага. В симуляторе — модель с ручкой-датчиком, кнопкой и порогом, который двигается командой из монитора.

Каркас — функция logBegin(uroven): она сравнивает уровень с порогом и, если строка допущена, печатает префикс — метку millis() и номер уровня. Вызывающий код дописывает свою часть и закрывает строку println. Один вызов решает три вещи сразу: фильтр стоит до печати, формат не размножается по скетчу, новый уровень добавляется числом, а не новой функцией. Уровней я держу три: 0 — DEBUG, 1 — INFO, 2 — WARN. Четвёртый уровень с реакцией из урока про уровни логов здесь не нужен: сбой, на который скетч отвечает реле и светодиодом, и есть WARN с растущим счётчиком.

Метка времени — millis() без делений, в самом начале строки. Секунды выглядят дружелюбнее, но интервалы тогда не считаются в уме: строки с метками 123000 и 124500 говорят сами за себя — разница полторы секунды. Сырая метка честнее к переполнению: millis() через 49,7 суток обнуляется, и вычитание двух беззнаковых чисел всё равно даёт правильный интервал, а с делёнными секундами и датой начинается путаница. Печатаю метку первой колонкой ещё и потому, что журнал уезжает в файл целиком: колонка меток сортируется, а поиск по «u2» достаёт одни предупреждения из десятков тысяч строк.

Строки собираю по частям, без String-склейки: Serial.print("opros v="), следом число. Причина описана в граблях уровней логов — временные String на каждый чих фрагментируют кучу из двух килобайт, и скетч молча замолкает через сутки. Литералы внутри макроса уходят во флеш через F() — механику считали в уроке про макрос F(); обёртка do-while(0) вокруг тела макроса — та же страховка, что у DBG-макросов: LOG после if без фигурных скобок не съест чужой else.

Скетч опрашивает датчик раз в секунду через планировщик, собранный на millis в уроке про millis вместо delay — никаких пауз, loop между делами крутится вхолостую. Каждый опрос DEBUG-строкой с v= виден только при пороге 0; значение у края диапазона поднимает счётчик и печатает WARN. Ничего лишнего: опросов за сутки — восемьдесят шесть тысяч, и в боевой сборке они не тратят ни байта канала, потому что отсекаются до печати.

Порог — константа POROG, и смена сборки — одна строка. На столе ставлю 0: вижу каждый опрос и каждый вход в ветку. Перед выездом в поле — 2: от дежурного потока остаются одни предупреждения, канал свободен для полезного груза. Для жёсткого случая, когда в бою не должно остаться даже вырезанных порогом строк во флеше, порог дополняется условной компиляцией из урока про DBG-макросы: ifdef вырежет вызовы вместе с литералами, порог — только из канала. Два слоя выглядят дублированием, но решают разные задачи: один экономит время, второй — байты.

Журнал с метками живёт дольше сессии с монитором: я сохраняю окно терминала в файл после каждой сессии и дальше работаю с ним как с текстом. После перезагрузки по watchdog millis обнуляется, и в журнале появляется разрыв — серия начинается с малого числа. Это и есть отметка о перезагрузке, ничего искать не надо: что положить в журнал на случай сбоя, разобрано в уроке про чёрный ящик — там же кольцевой буфер последних событий.

Цена строки — арифметика, которую полезно держать в голове. При 9600 бод канал отдаёт около 960 символов в секунду, строка логгера в тридцать символов с меткой и уровнем стоит около 31 мс. DEBUG-поток раз в секунду — три процента канала, раз в сто миллисекунд — уже треть, а в горячем цикле без планировщика печать и вовсе растягивает loop до скорости провода. При 115200 всё легче в двенадцать раз, но правило не меняется: что не прошло порог, то не платит. Поэтому фильтр стоит до печати, а не после — отсечённая строка не доходит даже до буфера.

В прерывании, повторюсь, лога нет: обработчик ставит флаг, печать делает loop. Если событие частое — дребезг кнопки, фронты энкодера, — флаги копятся в счётчик, и DEBUG-строка печатает его раз в секунду: видно и частоту, и пачки. Механику фронтов и обработчиков разбирали в уроке про attachInterrupt; я применяю пару «прерывание плюс логгер» на счётчике оборотов и на зуммере — момент события даёт прерывание, картину даёт лог, и друг другу они не мешают.

Моё правило сборок: на столе — порог 0, первую ночь в поле — 1, дальше — 2. Условие, при котором я отступаю: если устройство передаёт лог по радио за батарейку, порог 2 стоит с первого включения, а INFO включается командой по запросу — тот же парсер команд, что соберём в следующем уроке, умеет переключать и уровни. Спорить, нужен ли DEBUG в бою, можно долго; мой ответ — пусть лежит во флеше за порогом: достать его командой дешевле, чем перешивать плату в поле.

Разберу реальное чтение журнала, чтобы стало ясно, зачем вся эта структура. Ночь на вторник: сначала WARN u2 с текстом v u kraya и счётчиком один, через три секунды — второй, с счётчиком два, дальше INFO про включение резервного тена, вписанного месяцем раньше. Три строки дали хронологию: подозрение началось в 2:04, реакция сработала через три секунды, интервалы видны вычитанием меток. До уровней этот же вечер занимал сорок минут прокрутки и заканчивался гаданием.

Счётчик подряд в WARN — половина пользы уровня: одиночное подозрение почти всегда шум датчика, три подряд — событие. Порог для действий я держу не в логгере, а в логике: логгер честно печатает каждое подозрение, решение принимает скетч. Так жёсткая связь «напечатал — значит среагировал» не возникает сама собой, и WARN от неудачной настройки не глушит тен без ведома автора.

И привычка, которая стоит дороже всех констант: новые строки DEBUG я пишу первыми, INFO и WARN — следом, а удаляю только те DEBUG, которые перестали быть нужны. Через полгода у скетча остаётся живой словарь событий: что устройство считает подозрительным и о чём докладывает. Такой словарь дешевле любого документирования — журнал сам показывает, что плата вообще умеет замечать.