event_log.c

Go to the documentation of this file.

/********************************** (C) COPYRIGHT *******************************
 * File Name          : event_log.c
 * Description        : Подробное логирование событий LCM на USART1 (PD6, 115200 8N1).
 *
 * USART1 TX — PD6 (GPIO_PartialRemap2_USART1), 115200, 8N1.
 * События из ISR складываются в кольцевой буфер; форматирование — в main.
 *********************************************************************************/
 
#include "event_log.h"
#include "lcm_module.h"
#include "ch32v00x_conf.h"
#include "core_riscv.h"
#include <stdarg.h>
#include <stdio.h>
 
#define EVENT_LOG_BAUD            115200U
#define EVENT_LOG_LINE_SIZE       96U
#define EVENT_LOG_RING_SIZE       48U
 
/*
 * Все события (включая I2C CMD/READ) идут через это кольцо и печатаются
 * только из EventLog_Process() в main. Важно: UART — общий ресурс; если
 * писать в него и из ISR (напрямую), и из main одновременно, символы
 * перемешиваются/бьются (напр. "0x" превращается в "0|"). Поэтому ISR
 * только кладёт запись в кольцо (короткая парная disable/enable_irq),
 * а реальная передача по UART — всегда из одного (main) контекста.
 */
typedef enum {
    EVT_LCM_ERR = 0,
    EVT_NVM,
    EVT_SYS,
    EVT_I2C_CMD,
    EVT_I2C_READ
} EventLog_Id;
 
/*
 * Компактная запись одного события в кольце: 4 байта вместо строки —
 * форматирование (snprintf, довольно «дорогое» по времени и стеку)
 * откладывается до EventLog_Process() в главном цикле. id выбирает
 * интерпретацию полей a/b/c — см. EventLog_Id и EventLog_FormatRecord().
 */
typedef struct {
    uint8_t id;
    uint8_t a;
    uint8_t b;
    uint8_t c;
} EventLog_Rec;
 
/*
 * Кольцевой буфер: s_ring_head — индекс следующей свободной ячейки (пишет
 * PushRaw), s_ring_tail — индекс следующей записи на вывод (двигает
 * Process). Буфер пуст, когда head == tail; заполнен, когда добавление
 * ещё одной записи сделало бы next(head) == tail — в этот момент PushRaw
 * молча отбрасывает событие (переполнение лога не должно ронять систему).
 * head/tail volatile, т.к. head пишется из ISR (через PushRaw), а tail —
 * из main (через Process); сами перезаписи защищены __disable_irq()/
 * __enable_irq() ниже.
 */
static volatile uint8_t s_ring_head;
static volatile uint8_t s_ring_tail;
static EventLog_Rec s_ring[EVENT_LOG_RING_SIZE];
static uint32_t s_seq;                       /* сквозной номер события для строки лога */
static char s_line[EVENT_LOG_LINE_SIZE];     /* общий буфер форматирования (только из main) */
 
#if EVENT_LOG_ENABLE
 
/*********************************************************************
 * @fn      EventLog_UartPutChar
 *
 * @brief   Отправить один байт по USART1 (блокирующе).
 *
 * @details Ждёт флаг TC (Transmission Complete) ПЕРЕД записью в DATAR,
 *          а не после — это гарантирует, что предыдущий байт (включая
 *          стоп-бит) уже полностью ушёл в линию до того, как мы положим
 *          новый байт в буфер данных USART. Вызывается только из главного
 *          цикла (через EventLog_UartWrite/Process/Printf) — прямой вывод
 *          из ISR запрещён (см. комментарий к структуре кольца выше и
 *          historical fix: конкурентная запись в USART1->DATAR из ISR и
 *          main одновременно ломала байты, напр. "0x" превращалось в "0|").
 */
static void EventLog_UartPutChar(char ch)
{
    while (USART_GetFlagStatus(USART1, USART_FLAG_TC) == RESET) {
    }
    USART_SendData(USART1, (uint16_t)(uint8_t)ch);
}
 
/*********************************************************************
 * @fn      EventLog_UartWrite
 *
 * @brief   Отправить C-строку по USART1 побайтно (до '\0').
 */
static void EventLog_UartWrite(const char *s)
{
    while (*s != '\0') {
        EventLog_UartPutChar(*s++);
    }
}
 
/*********************************************************************
 * @fn      EventLog_UartInit
 *
 * @brief   USART1, PD6 TX, 115200 8N1.
 *
 * @details PD6 — не штатный вывод TX для USART1 (по умолчанию это PD5);
 *          используется альтернативная схема выводов PartialRemap2
 *          (GPIO_PinRemapConfig), поэтому AFIO-тактирование обязательно
 *          включается до вызова GPIO_PinRemapConfig(). Режим приёма (RX)
 *          не настраивается — USART_Mode_Tx, модуль только пишет в лог,
 *          обратный канал не нужен.
 */
static void EventLog_UartInit(void)
{
    GPIO_InitTypeDef gpio = {0};
    USART_InitTypeDef usart = {0};
 
    RCC_APB2PeriphClockCmd(RCC_APB2Periph_GPIOD | RCC_APB2Periph_USART1 | RCC_APB2Periph_AFIO, ENABLE);
    GPIO_PinRemapConfig(GPIO_PartialRemap2_USART1, ENABLE);
 
    gpio.GPIO_Pin = GPIO_Pin_6;
    gpio.GPIO_Speed = GPIO_Speed_30MHz;
    gpio.GPIO_Mode = GPIO_Mode_AF_PP;   /* альтернативная функция, push-pull (не open-drain) */
    GPIO_Init(GPIOD, &gpio);
 
    USART_DeInit(USART1);
    usart.USART_BaudRate = EVENT_LOG_BAUD;
    usart.USART_WordLength = USART_WordLength_8b;
    usart.USART_StopBits = USART_StopBits_1;
    usart.USART_Parity = USART_Parity_No;
    usart.USART_HardwareFlowControl = USART_HardwareFlowControl_None;
    usart.USART_Mode = USART_Mode_Tx;
    USART_Init(USART1, &usart);
    USART_Cmd(USART1, ENABLE);
}
 
/*********************************************************************
 * @fn      EventLog_PushRaw
 *
 * @brief   Положить компактную запись события в кольцевой буфер.
 *
 * @param   id, a, b, c — см. EventLog_Id и EventLog_FormatRecord()
 *          (интерпретация полей a/b/c зависит от id).
 *
 * @details Вызывается как из главного цикла, так и из I2C ISR (через
 *          EventLog_PushI2cCmd/PushI2cReadArm/PushLcmError и т.д.),
 *          поэтому доступ к s_ring_head защищён __disable_irq()/
 *          __enable_irq(). Это НЕ противоречит правилу «не звать
 *          disable/enable_irq в WCH-Interrupt-fast» (см. lcm_led.c) —
 *          там проблема была в НЕСБАЛАНСИРОВАННОМ вызове (disable в
 *          начале ISR без гарантированного enable перед выходом). Здесь
 *          пара вызовов всегда выполняется целиком внутри одной короткой
 *          функции — при любом пути выхода (переполнение или запись)
 *          __enable_irq() гарантированно вызывается до return, поэтому
 *          биты MIE/MPIE в mstatus восстанавливаются симметрично и mret
 *          после выхода из ISR не оставит прерывания выключенными навсегда.
 *
 *          Если буфер заполнен (next(head) == tail), событие тихо
 *          отбрасывается — переполнение лога не должно блокировать или
 *          ронять основную логику (I2C/реле).
 */
static void EventLog_PushRaw(uint8_t id, uint8_t a, uint8_t b, uint8_t c)
{
    uint8_t head;
    uint8_t next;
 
    __disable_irq();
    head = s_ring_head;
    next = (uint8_t)((head + 1U) % EVENT_LOG_RING_SIZE);
    if (next == s_ring_tail) {
        __enable_irq();
        return;
    }
 
    s_ring[head].id = id;
    s_ring[head].a = a;
    s_ring[head].b = b;
    s_ring[head].c = c;
    s_ring_head = next;
    __enable_irq();
}
 
/*********************************************************************
 * @fn      EventLog_LcmErrName
 *
 * @brief   Символьное имя кода ошибки LCM_ERR_* для строки лога.
 *
 * @param   code — значение LCM_ERR_* (lcm_module.h).
 *
 * @return  Короткое имя без префикса LCM_ERR_ (напр. "BAD_PARAM");
 *          "UNKNOWN" — если code не входит ни в один известный диапазон
 *          (защита от рассинхронизации со списком в lcm_module.h).
 */
static const char *EventLog_LcmErrName(uint8_t code)
{
    switch (code) {
    case LCM_ERR_NONE:              return "NONE";
    case LCM_ERR_UNKNOWN_CMD:       return "UNKNOWN_CMD";
    case LCM_ERR_BAD_PARAM:         return "BAD_PARAM";
    case LCM_ERR_I2C_BERR:          return "I2C_BERR";
    case LCM_ERR_I2C_OVR:           return "I2C_OVR";
    case LCM_ERR_I2C_ARLO:          return "I2C_ARLO";
    case LCM_ERR_USER_DATA_COMMIT:  return "UD_COMMIT";
    case LCM_ERR_USER_DATA_PARAM:   return "UD_PARAM";
    case LCM_ERR_USER_DATA_RANGE:   return "UD_RANGE";
    case LCM_ERR_USER_DATA_FLASH:   return "UD_FLASH";
    case LCM_ERR_USER_DATA_BUSY:    return "UD_BUSY";
    case LCM_ERR_GPIO_INIT:         return "GPIO_INIT";
    case LCM_ERR_GPIO_SET:          return "GPIO_SET";
    case LCM_ERR_GPIO_GET:          return "GPIO_GET";
    case LCM_ERR_GPIO_CLEAR:        return "GPIO_CLEAR";
    case LCM_ERR_GPIO_SET_ALL:      return "GPIO_SET_ALL";
    case LCM_ERR_GPIO_CLEAR_ALL:    return "GPIO_CLEAR_ALL";
    default:                        return "UNKNOWN";
    }
}
 
/*********************************************************************
 * @fn      EventLog_UserDataName
 *
 * @brief   Символьное имя UserData_Status для строки лога NVM-событий.
 *
 * @param   st — значение из перечисления UserData_Status (user_data.h),
 *          переданное как uint8_t (сами события в кольце хранят статус
 *          именно так — компактной записью в 1 байт).
 */
static const char *EventLog_UserDataName(uint8_t st)
{
    switch (st) {
    case USER_DATA_OK:          return "OK";
    case USER_DATA_ERR_PARAM:   return "PARAM";
    case USER_DATA_ERR_RANGE:   return "RANGE";
    case USER_DATA_ERR_FLASH:   return "FLASH";
    case USER_DATA_ERR_BUSY:    return "BUSY";
    default:                    return "?";
    }
}
 
/*********************************************************************
 * @fn      EventLog_FormatRecord
 *
 * @brief   Развернуть компактную запись EventLog_Rec в текстовую строку
 *          и вывести её на UART.
 *
 * @details Вызывается только из EventLog_Process() (главный цикл) —
 *          использует общий static-буфер s_line и медленный snprintf,
 *          поэтому не годится для вызова из ISR.
 *
 *          Числовое поле rec->a для EVT_NVM/EVT_SYS — это условный «tag»
 *          источника события (не входит в отдельный enum, т.к. кодируется
 *          прямо в вызовах EventLog_PushNvm/PushSystem из lcm_module.c):
 *            EVT_NVM:  1 — запись в RAM-кэш user_data (LCM_NvmWriteConfig/
 *                          LCM_LoadConfig), rec->b = UserData_Status;
 *                      2 — результат UserData_Commit() (сама запись во
 *                          flash), rec->b = UserData_Status;
 *                      3 — сброс кэша к заводским значениям при LCM_RESET,
 *                          rec->b = UserData_Status.
 *            EVT_SYS:  1 — запрошена программная перезагрузка (перед
 *                          NVIC_SystemReset(), после SET_ADDR/LCM_RESET);
 *                      2 — IWDG успешно взведён (~2 c) при старте.
 *          Любое иное значение tag печатается «как есть» (fallback-ветка
 *          "NVM event tag=… " / "SYS tag=…") — это защита от рассинхронизации,
 *          если в lcm_module.c/main.c добавят новый tag без обновления
 *          этой функции.
 */
static void EventLog_FormatRecord(const EventLog_Rec *rec)
{
    s_seq++;
    switch (rec->id) {
    case EVT_I2C_CMD:
        if (rec->c) {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] I2C CMD 0x%02X param=0x%02X\r\n",
                     (unsigned long)s_seq, rec->a, rec->b);
        } else {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] I2C CMD 0x%02X\r\n",
                     (unsigned long)s_seq, rec->a);
        }
        break;
 
    case EVT_I2C_READ:
        snprintf(s_line, sizeof(s_line),
                 "[%lu] I2C READ arm cmd=0x%02X\r\n",
                 (unsigned long)s_seq, rec->a);
        break;
 
    case EVT_LCM_ERR:
        snprintf(s_line, sizeof(s_line),
                 "[%lu] ERROR %s (0x%02X)\r\n",
                 (unsigned long)s_seq, EventLog_LcmErrName(rec->a), rec->a);
        break;
 
    case EVT_NVM:
        if (rec->a == 1U) {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] NVM cache_write %s\r\n",
                     (unsigned long)s_seq, EventLog_UserDataName(rec->b));
        } else if (rec->a == 2U) {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] NVM commit %s\r\n",
                     (unsigned long)s_seq, EventLog_UserDataName(rec->b));
        } else if (rec->a == 3U) {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] NVM factory_reset cache %s\r\n",
                     (unsigned long)s_seq, EventLog_UserDataName(rec->b));
        } else {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] NVM event tag=%u st=%u\r\n",
                     (unsigned long)s_seq, rec->a, rec->b);
        }
        break;
 
    case EVT_SYS:
        if (rec->a == 1U) {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] SYS reboot requested\r\n", (unsigned long)s_seq);
        } else if (rec->a == 2U) {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] SYS IWDG armed (~2 s)\r\n", (unsigned long)s_seq);
        } else {
            snprintf(s_line, sizeof(s_line),
                     "[%lu] SYS tag=%u\r\n", (unsigned long)s_seq, rec->a);
        }
        break;
 
    default:
        snprintf(s_line, sizeof(s_line),
                 "[%lu] EVT id=%u a=%u b=%u c=%u\r\n",
                 (unsigned long)s_seq, rec->id, rec->a, rec->b, rec->c);
        break;
    }
    EventLog_UartWrite(s_line);
}
 
void EventLog_Init(void)
{
    s_ring_head = 0U;
    s_ring_tail = 0U;
    s_seq = 0U;
    EventLog_UartInit();
}
 
/*
 * Внешний while() читает s_ring_tail/head без блокировки прерываний —
 * это лишь быстрая проверка «есть ли вообще что обрабатывать», не
 * гарантирующая согласованность (ISR может добавить запись в любой
 * момент). Настоящее извлечение элемента — под __disable_irq(), с
 * повторной проверкой условия внутри (на случай, если ISR успела
 * забрать последнее событие между проверкой снаружи и входом в секцию).
 * EventLog_FormatRecord() (snprintf + побайтная отправка по UART,
 * потенциально десятки микросекунд) выполняется УЖЕ ПОСЛЕ __enable_irq() —
 * критическая секция защищает только сам доступ к индексам/массиву
 * кольца, а не форматирование и вывод, чтобы не держать прерывания
 * выключенными дольше необходимого (I2C ISR не должна ждать снаружи).
 */
void EventLog_Process(void)
{
    EventLog_Rec rec;
 
    while (s_ring_tail != s_ring_head) {
        __disable_irq();
        if (s_ring_tail == s_ring_head) {
            __enable_irq();
            break;
        }
        rec = s_ring[s_ring_tail];
        s_ring_tail = (uint8_t)((s_ring_tail + 1U) % EVENT_LOG_RING_SIZE);
        __enable_irq();
        EventLog_FormatRecord(&rec);
    }
}
 
/*
 * В отличие от EventLog_Push*(), пишет на UART немедленно и синхронно —
 * поэтому вызывать только из main (см. @brief в event_log.h). vsnprintf
 * возвращает отрицательное значение при внутренней ошибке форматирования
 * (сюда не должно доходить при корректных fmt/аргументах) — в этом случае
 * s_line не трогаем и ничего не выводим, чтобы не отправить в UART мусор
 * из предыдущего вызова.
 */
void EventLog_Printf(const char *fmt, ...)
{
    va_list ap;
    int n;
 
    va_start(ap, fmt);
    n = vsnprintf(s_line, sizeof(s_line), fmt, ap);
    va_end(ap);
 
    if (n <= 0) {
        return;
    }
    EventLog_UartWrite(s_line);
}
 
void EventLog_BootBanner(void)
{
    EventLog_Printf(
        "\r\n=== LCM event log USART1 PD6 %u 8N1 ===\r\n"
        "MCU CH32V003F4P6  LCM_ID=0x%02X\r\n",
        (unsigned)EVENT_LOG_BAUD, (unsigned)LCM_ID);
}
 
void EventLog_UserDataInit(UserData_Status st)
{
    if (st == USER_DATA_OK) {
        EventLog_Printf("[%lu] BOOT UserData_Init OK\r\n", (unsigned long)(++s_seq));
    } else {
        EventLog_Printf("[%lu] BOOT UserData_Init FAIL %s\r\n",
                        (unsigned long)(++s_seq), EventLog_UserDataName((uint8_t)st));
    }
}
 
void EventLog_LcmConfig(uint8_t i2c_addr, const uint8_t group_mask[4], uint8_t relay_state)
{
    EventLog_Printf(
        "[%lu] BOOT LCM addr=0x%02X groups=%02X %02X %02X %02X relay=0x%02X\r\n",
        (unsigned long)(++s_seq),
        (unsigned)i2c_addr,
        (unsigned)group_mask[0], (unsigned)group_mask[1],
        (unsigned)group_mask[2], (unsigned)group_mask[3],
        (unsigned)relay_state);
}
 
void EventLog_PushI2cCmd(uint8_t cmd, uint8_t param, uint8_t has_param)
{
    EventLog_PushRaw(EVT_I2C_CMD, cmd, param, has_param);
}
 
void EventLog_PushI2cReadArm(uint8_t cmd)
{
    EventLog_PushRaw(EVT_I2C_READ, cmd, 0U, 0U);
}
 
void EventLog_PushLcmError(uint8_t lcm_err_code)
{
    EventLog_PushRaw(EVT_LCM_ERR, lcm_err_code, 0U, 0U);
}
 
void EventLog_PushNvm(uint8_t tag, uint8_t status)
{
    EventLog_PushRaw(EVT_NVM, tag, status, 0U);
}
 
void EventLog_PushSystem(uint8_t tag)
{
    EventLog_PushRaw(EVT_SYS, tag, 0U, 0U);
}
 
#else /* EVENT_LOG_ENABLE */
 
void EventLog_Init(void) {}
void EventLog_Process(void) {}
void EventLog_Printf(const char *fmt, ...) { (void)fmt; }
void EventLog_BootBanner(void) {}
void EventLog_UserDataInit(UserData_Status st) { (void)st; }
void EventLog_LcmConfig(uint8_t i2c_addr, const uint8_t *group_mask, uint8_t relay_state)
{
    (void)i2c_addr;
    (void)group_mask;
    (void)relay_state;
}
void EventLog_PushI2cCmd(uint8_t cmd, uint8_t param, uint8_t has_param)
{
    (void)cmd; (void)param; (void)has_param;
}
void EventLog_PushI2cReadArm(uint8_t cmd) { (void)cmd; }
void EventLog_PushLcmError(uint8_t lcm_err_code) { (void)lcm_err_code; }
void EventLog_PushNvm(uint8_t tag, uint8_t status) { (void)tag; (void)status; }
void EventLog_PushSystem(uint8_t tag) { (void)tag; }
 
#endif /* EVENT_LOG_ENABLE */