Уровни логов: debug, info, warn и error

Поливалка на моём балконе честно проработала месяц, а сломалась — в самый жаркий день, когда меня не было дома. Скетч у неё был дотошный: каждые двести миллисекунд печатал в порт строку вида v=412 nasos=0. За сутки таких строк набегает около четырёхсот тысяч, и монитор порта превращается в конвейер одинакового текста. Тем вечером я листал историю назад в поисках момента, когда насос должен был включиться и не включился, — глаз по строке в секунду, и через сорок минут я поймал себя на мысли, что не ищу проблему, а сортирую мусор. Строки не ранжированы: обычный опрос датчика, лёгкая странность и настоящая катастрофа выглядят в них совершенно одинаково.

И это не только моя беда. Сорок строк в минуту — пока всё работает, каждая выглядит полезной. Но тем вечером мне была нужна одна-единственная строка, та, где датчик замолчал, — и я не мог отличить её от сотни соседних. У строк нет веса: рутинный дебаг, предупреждение и ошибка стоят в одной очереди с равными правами. Данные в них были честные: датчик действительно опрашивался, насос действительно был выключен. Проблема была в подаче. Листать такое можно всю ночь — я и листал, с третьего часа и до подъёма.

Лекарство старше Arduino на десятилетия: уровни логов. В серверном syslog у сообщений есть severity, в Android — LogCat с метками, в консоли браузера — console.debug, console.info, console.warn и console.error, и вы наверняка видели, как там жёлтое и красное отсекается от рутины одним взглядом. В этом уроке переносим тот же порядок в скетч: единый формат строки — метка уровня, метка времени из millis(), текст, — три функции-обёртки вместо голого Serial.print и правило двойного подтверждения, чтобы ложное срабатывание оставалось строкой warn, а не сиреной. Печатать в порт мы научились в первом уроке про монитор порта; теперь научимся печатать так, чтобы журнал через месяц не было стыдно листать.

Уровней в больших системах бывает от шести до восьми — у syslog целая лестница от Emergency до Debug. Для скетча на Uno хватает четырёх, и запоминать их лучше не по номерам, а по одному вопросу: что устройство делает в момент, когда произносит эту строку? Ничего — это info. Готовится — warn. Действует — error. А ничего и вообще зря печатал — debug.

Debug — внутренности: значения переменных, входы в функции, сырые коды датчиков. Такие строки нужны, пока вы чините, и мешают, когда починили: их отключает первой же строка-константа. Info — нормальный ход: старт, нажатая кнопка, контрольный замер раз в пять-десять секунд. Warn — подозрение: датчик первый раз ответил ниже порога, но ещё не подтвердил; устройство работает, но уже считает. Error — сбой подтверждён, и скетч реагирует: зажигает красный светодиод, глушит насос, уходит в резервный режим.

Ключевая развилка — между warn и error. Я поначалу писал всё в одну кучу: что-то странное — и сразу ОШИБКА, большими буквами. Через неделю красного в журнале стало столько, что глаз перестал цепляться. Тогда появилось правило двойного подтверждения: первый странный опрос даёт warn и счётчик, второй подряд — error и действие. Ложное срабатывание живёт в журнале одной строкой warn и строкой info про восстановление, а сирена включается только по-настоящему.

Второй вопрос, на который отвечает формат, — когда это случилось. Метка времени из millis() внутри строки экономит вечер: строка [W] t=4127s говорит не только «подозрение», но и «на четыре тысячи сто двадцать седьмой секунде после старта», а если скетч печатал и состояние насоса, вы сопоставляете два события по числам, а не по памяти. Метка уровня стоит в начале строки не для красоты: монитор Arduino IDE не умеет ни фильтровать, ни искать по журналу, зато весь лог копируется в файл — и одна команда grep по [E] достаёт все ошибки из сорока тысяч строк. Я разбираю ночные логи именно так: сначала [E], потом [W] вокруг них, а рутину [I] читаю, только если оба уровня ничего не объяснили.

И фильтр — в скетче, а не в мониторе. Монитор порта на Uno строки прятать не умеет, зато умеет скетч: константа UROVEN_LOGA, и сообщение ниже уровня даже не отправляется в порт. На 9600 бод это не педантичность: символ стоит около миллисекунды, и невычеркнутый debug в горячем цикле платит за место в журнале реальным временем loop. К числам вернёмся в граблях, а карта уровней — в таблице.

Первая грабля — арифметическая. На 9600 бод при кадре 8N1 на байт уходит десять бит, выходит около 960 символов в секунду — почти миллисекунда на символ. Строка в тридцать символов занимает около тридцати мс: печатать её каждые десять нельзя, TX-буфер Uno на 64 байта переполняется, Serial.print превращается из «отдать и забыть» в «подождать места», и loop растягивается до скорости канала. У меня контрольный цикл с тридцатисимвольной печатью раз в 10 мс съедал около двух третей времени. На 115200 лёгче — 11,5 КБ в секунду, — но тонна debug в горячем цикле и там ощутима. При этом печать раз в двести мс, как у поливалки, брала около тринадцати процентов канала — это нормально: проблема не в том, что печатать нельзя, а в том, что печатать много и одинаково.

Вторая грабля — уровни без системы. Пометить всё [E], «чтобы заметнее», — самая человеческая ошибка, и я её сделал: через неделю красного в журнале стало столько, что он перестал быть сигналом. Рабочая пропорция у моей поливалки получилась такая: info — единицы строк в минуту, warn — единицы в день, error — считанные разы за сезон, и каждый — с действием.

Третья грабля — платная, и мы её уже проходили. Склейка v= со String(v) перед каждым println заводит объект в куче: символы плюс служебные поля, а после освобождения — дырка. В уроке про макрос F() мы только что выгоняли литералы из оперативки — и я же зазываю их обратно самодельным логгером. Лечение простое: печатать по частям, Serial.print("v=") и следом Serial.print(v), — строка не заводится вовсе, а формат от этого не страдает. HEX- и BIN-добавки к меткам ставятся тем же вторым аргументом печати, что мы разобрали в прошлом уроке про системы счисления.

Формат строки собирается тремя кусками: метка уровня в квадратных скобках, метка времени и текст. Время берём из millis(), делённого на тысячу, — в секундах: сам таймер на millis() вместо delay() разобран в отдельном уроке, здесь он вписан в маленькую функцию stamp(). Печать — по частям, без единого String: Serial.print("[I] "), stamp(), пробел, сообщение.

Дальше — функции-обёртки, прямое продолжение урока про свои функции: logInfo, logWarn и logError принимают готовый текст и добавляют метку с уровнем. Формат живёт в одном месте: захотели HEX-метку millis() из прошлого урока — правите stamp(), а не сорок вызовов по всему скетчу. В полной версии из скетча ниже есть и logDebug с фильтром UROVEN_LOGA: сообщение ниже уровня обрывается голым return, даже не начав печататься.

Логика уровней — обычные ветки if/else из урока про условия. Опрос раз в секунду: значение ниже порога — поднимаем счётчик странных опросов; первый такой — warn, второй подряд — error, красный светодиод, зелёный гаснет. Значение вернулось, а счётчик был поднят — печатаем info про выздоровление и сбрасываем счётчик. Каждые пять секунд в норме — контрольная строка info, чтобы журнал дышал. В симуляторе ниже — компактная версия: ползунок A0 изображает капризный датчик, светодиоды на пинах 7 и 8 — реакцию устройства.