Отладка Программ Уровнями Логирования (или Медицинская Карта Вашей Программы)

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

Чтобы с этим бороться давным-давно придумали фундаментальную технологию отладки программ: уровни логирования (Log Levels). Как и любая хорошая практика системного программирования, уровни логирования появились еще в коде ОС Unix где-то в 197x-198x.

Суть в том, чтобы из shell консоли в run time можно было включать или отключить логи для конкретных программных компонентов. Более того, для каждого программного компонента есть пять основных уровней логирования: critical, error, info , debug, paranoid. Отдельными командами вы можете увеличивать или уменьшать многословность (verbosity) логирования. Это позволяет Вам сфокусировать внимание на конкретном программном компоненте и найти суть ошибки в программе или, например, причину по которой не проходит конкретный модульный тест.

Уровни логирования обычно нужны для снятия покрытия кода логами при выяснении причин сбоев. Уровень логирования следует задавать запросами в UART CLI командой LogLevel (ll). Например команда ll usb debug активирует отладочное логирование для модуля USB. Команда ll usb parn активирует многословное логирование для модуля USB. А команда ll can parn активирует самое многословное логирование для модуля CAN. И так далее. Вот вам яркий пример. Вы можете запустить функцию расчета коэффициентов PLL с уровнем логирования info

А можете предварительно отдельной командой ll pll debug сперва настроить для программного компонента PLL уровень логирования debug. И только после этого запустить функцию расчета коэффициентов PLL.

Тогда вы получите более подробный лог, который уже не просто выдает решение, но и покажет как алгоритм программы итеративно пришел к этому решению. Затем можно уже вернуть обратно исходный уровень логирования info прописав в консоли команду ll pll info.

Отсюда можно вынести следующие выводы.

1) Любую программу и прошивку надо строить из набора отдельных программных компонентов.

2) Для работы с уровнями логирования в программе должен быть реализован интерфейс командной строки. То есть CLI. Он же shell. Он же TUI.

3) В коде, который мы хотим отладить, надо расставить функции макросы LOG_ERROR(FASILITY,…), LOG_WARNING(FASILITY,…), LOG_INFO(FASILITY,…) , LOG_DEBUG(FASILITY,…), LOG_NOTICE(FASILITY,…) , LOG_PARN(FASILITY,…) и т. д. Прототип у них такой же, как у printf + первый аргумент для указания источника логирования.

void log_write(log_level_t level, facility_t facility, const char* format, ...) {
#ifdef HAS_STREAM
    bool res = log_write_prefix(level, facility);
    if(res) {
        va_list va;
        va_start(va, format);
        cli_vprintf(format, va);
        va_end(va);
        log_write_end();
    }
#endif
}

void LOG_WARNING(facility_t facility, const char* format, ...) {
#ifdef HAS_STREAM
    if(log_write_prefix(LOG_LEVEL_WARNING, facility)) {
        va_list va;
        va_start(va, format);
        cli_vprintf(format, va);
        va_end(va);
        log_write_end();
    }
#endif
}

void LOG_DEBUG(facility_t facility, const char* format, ...) {
#ifdef HAS_STREAM
    if(log_write_prefix(LOG_LEVEL_DEBUG, facility)) {
        va_list va;
        va_start(va, format);
        cli_vprintf(format, va);
        va_end(va);
        log_write_end();
    }
#endif
}

Заметьте макрос HAS_STREAM. Если вам не нужен уровень логирования то вы просто убираете из ключей сборки -DHAS_STREAM. B результате макро-функции LOG_XXX() просто вставляют пустоту и релизная программа без помех работает на крейсерской скорости.

4) У каждого программного компонента должен быть униrальный ID, обозначающий facility, чтобы программный компонент логирования заменил его в логи на текстовый токен в консоли.

typedef enum {
    SYS= -1 ,
    UNKNOWN_FACILITY = 0, /*must be first in enum*/
#ifdef HAS_ACC
    LG_ACC,
#endif
.....
#ifdef HAS_GPIO
    GPIO,
#endif

#ifdef HAS_SPI
    SPI,
#endif

....
    ALL_FACILITY, /*must be last in enum*/
} facility_t;

Программный компонент логирования заменяет числовые токены facility_t на строки, чтобы пользователь мог визуально понять какая именно часть программы выдала сообщение в UART.

typedef struct{
    facility_t facility;
    char* name;
}FacilityInfo_t;

#ifdef HAS_MPU
#define MPU_FACILITY_DIAG                                                                                              
    {                                                                                                                  
        .facility = LG_MPU,                                                                                            
        .name = "Mpu",                                                                                                 
    },
#else
#define MPU_FACILITY_DIAG
#endif

#ifdef HAS_EEPROM
#define EEPROM_FACILITY_DIAG                                                                                           
    {                                                                                                                  
        .facility = EEPROM,                                                                                            
        .name = "EEPROM",                                                                                              
    },
#else
#define EEPROM_FACILITY_DIAG
#endif

static const FacilityInfo_t FacilityInfo[] = {
   ...
    EEPROM_FACILITY_DIAG
    MPU_FACILITY_DIAG
    ...
};

5) Вам придется писать так называемые сериализиторы. Сейчас объясню, что это такое. У каждого программного компонента есть куча всяческих констант и спец структур. Значения констант подобраны вендором обычно специфические. Просто глядя на константу ничего про нее сказать нельзя. Поэтому эти константы надо интерпретировать в строки для человека-понимания. Аналогично с типами данных. Поэтому в каждом программном компоненте вам придется создать отдельный файл xxx_diag.с с функциями-отображениями (сериализаторами).

const char* DacLevel2Str(uint8_t code){
    const char *name="?";
    switch(code){
        case DAC_LEV_CTRL_INTERNALY: name="internally"; break;
        case DAC_LEV_CTRL_LOW:       name="low"; break;
        case DAC_LEV_CTRL_MEDIUM:    name="medium"; break;
        case DAC_LEV_CTRL_HIGH:      name="high"; break;
        default:      name="??"; break;
    }
    return name;
}

const char* SpiConfigToStr(const SpiConfig_t* const Config) {
    strcpy(text,"");
    if(Config) {
        sprintf(text, "SPI%u", Config->num);
        snprintf(text, sizeof(text), "%sRate:%u Hz,", text, Config->bit_rate_hz);
        snprintf(text, sizeof(text), "%sBitOrder:%s,", text, SpiBtOrdToStr(Config->bit_order));
        snprintf(text, sizeof(text), "%sPha:%s", text, SpiPhaseToStr(Config->phase));
        snprintf(text, sizeof(text), "%sPol:%s,", text, SpiPolarityToStr(Config->polarity));
        snprintf(text, sizeof(text), "%sCS:%s,", text, SpiCSelModToStr(Config->chip_select));
        snprintf(text, sizeof(text), "%sIRQp:%u,", text, Config->irq_priority);
        snprintf(text, sizeof(text), "%s%s,", text, Config->name);
        snprintf(text, sizeof(text), "%sMOSI:%s,", text, GpioPadToStr(Config->PadMosi));
        snprintf(text, sizeof(text), "%sMISO:%s,", text, GpioPadToStr(Config->PadMiso));
        snprintf(text, sizeof(text), "%sCS:%s,", text, GpioPadToStr(Config->PadCs));
        snprintf(text, sizeof(text), "%sSCK:%s,", text, GpioPadToStr(Config->PadSck));
    }
    return text;
}

Суть проста: даешь бинарное значение константы (или указатель на структуру) и тут же получаешь её значение в виде текстовой строчки. Аналогично с типами данных. Даешь указатель на структуру, получаешь ее представление в виде строки. Это и есть диагностика. Эти функции-отображения как раз вызывает CLI-шка и компонент логирования при логе инициализации программы. Это пожалуй самая большая часть работы по внедрению уровней логирования в Legacy проекты. Но благодаря DeepSeek вы можете переложить задачи по написанию сериализаторов для уровней логирования на нейросети.

Минные поля в коде

Перед тем как использовать логирование вы в смоем коде должны расставить макрофункции LOG_XXX логирования (мины). Например в случае возникновения ошибок вызывать макрос LOG_ERROR(SW_COM,”…”,…) для отладки написать LOG_DEBUG(SW_COM,”…”,…). После чего пересобрать программу и загрузить бинарь в target устройство. Логи красной нитью должны пронизывать весть ваш код.

Какие бывают уровни логирования?
Если коротко, то какие захотите, такие и будут. Я обычно использую вот эти. Это уже классика.

typedef enum {
    LOG_LEVEL_UNKNOWN = -5,
    LOG_LEVEL_PARANOID = -4,
    LOG_LEVEL_DEBUG = -3,
    LOG_LEVEL_PROTECTED = -2,
    LOG_LEVEL_NOTICE = -1,
    LOG_LEVEL_INFO = 0,
    LOG_LEVEL_WARNING = 1,
    LOG_LEVEL_ERROR = 2,
    LOG_LEVEL_CRITICAL = 3,
    LOG_LEVEL_COVERAGE = 4,
    LOG_LEVEL_DISABLE = 5,
    LOG_LEVEL_LAST = LOG_LEVEL_DISABLE
} log_level_t;

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

LOG_LEVEL_WARNING
Сообщения группы WARNING для сообщений типа предупреждений. События, регистрируемые на уровне WARN, обычно указывают на то, что произошло что-то неожиданное Условно, если появляется WARNING, то надо ехать в сервисный центр. Да можно какое-то время попользоватьcя программой, но если ничего не делать, то появятся сообщения ERROR.

LOG_LEVEL_ERROR
Сообщениями группы ERROR помечаем только сообщения об ошибках в программе. Обычно это требует вмешательства разработчика. Для пересборки программы с другими конфигами или поиска аппаратных дефектов на PCB.

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

LOG_LEVEL_DEBUG
Сообщения группы DEBUG нацелены для ценной в отладочных целях информации. Например временные данные. Всё то что поможет найти причину поломки в случае возникновения ошибки в программе. Debug предназначен для логирования подробной информации о системе для целей отладки.

LOG_LEVEL_NOTICE

Сообщения группы Notice относится к нормальным, но значимым условиям, которые могут потребовать внимания инженера или техника.

LOG_LEVEL_INFO
Сообщения группы INFO – это для логов информативного характера. Эти сообщения обычно говорят, что система работает нормально. Обычно сообщения группы INFO делают приятным зеленым цветом.

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

У уровней логирования есть иерархия. Если вы установили NOTICE, то в консоль будут печататься не только NOTICE, но и все уровни логирования, которые выше. То есть INFO, WARNING, ERROR, CRITICAL, COVERAGE и пр. Получается, если вы хотите совcем уж отключить логирования для , например, GPIO, то можно просто исполнить в консоли команду ll GPIO Disable. Аналогично для печати всех логов для SPI надо прописать ll spi parn.

LogLevel в программе оформлен как отдельный программный компонент со своим API. Можно в run time активировать или отключить поддержку цветов. Активировать или отключить тайм-штампы в сообщениях.

Вы можете получить список всех программных компонентов их которых состоит программа командой ll

Вы можете задать уровень логирования для конкретного программного компонента, например array, командой ll.

С более глубоким уровнем логирования можно проанализировать работу программного компонента CSV, при разборе shell команд

Достоинства отладки программ уровнями логирования

++Благодаря уровням логирования вы редко будете вспоминать про пошаговую отладку. Вам всё будет понятно по разноцветным логам в TeraTerm. Пошаговая отладка вам понадобится только в случае тотального зависания прошивки.

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

++Вы практически мгновенно получается исходные данные и целеуказание на причину бага. Достаточно прописать уровень логирования debug, прогнать модельный тест и Вы получаете в UART красочный отчет, который в общем-то уже, буквально как лакмусовая бумажка цветом, покажет на каком этапе программа ушла не туда. Вам не надо будет каждый раз по три часа прочесывать код пошаговым GDB отладчиком, чтобы, наконец, наткнутся на причину программного бага. Уровни логирования просто подсветят строчку кода красным или синим текстом после первого же прогона кода.

++Благодаря уровням логирования вы можете делать Code Coverage. Да… Просто в каждую функцию первой строкой добавляете строку LOG_COVERAGE(SYS,“%s()”,__FUNCTION__);

bool system_mcal_init(void) {
    LOG_COVERAGE(SYS,"%s()",__FUNCTION__);
    bool res = true;
    uint32_t cnt = system_init_get_cnt();
    res = system_init_one(SystemInitInstance, cnt);
    return res;
}

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

++Уровни логирования также позволяют регулировать объем генерируемых вашим приложением логов, чтобы записывалась только релевантная и необходимая информация, что минимизирует требования к хранилищу и обеспечивает эффективное управление логами. Надо учитывать, что у UART есть ограниченная пропускная способность. А SPI-flash это не черная дыра и тоже рано или позно переполнится. Любая память может закончиться. Надо отбрасывать ненужные логи и переносить их в категорию parn.

++Уровнями логирования вы можете эффективно отлаживать прошивки микроконтроллеров в которых нет JTAG интерфейса. Например esp32 или AVR.

++В сообщениях уровня логирования есть порядковый номер сообщения. Вы можете контролировать потерю пакетов и , тем самым, визуально тестировать среду передачи данных, будь то UART, RS485, CAN, ETH и т.п.

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

–Включение глубокого уровня логирования ( parn или coverage ) генерирует значительный объем вывода, который может существенно увеличить размер файлов логов, операции ввода-вывода и вычислительные накладные расходы. От обильного наплыва логов может не хватить пропускной способности UART.

Итоги

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

Благодаря уровням логирования вы редко будете вспоминать про пошаговую GDB отладку. Вам всё будет понятно по разноцветным логам в TeraTerm. А пошаговая отладка вам понадобится только в случае тотального зависания прошивки.

Используйте уровни логирования.

Больше ссылок