log fixup

This commit is contained in:
Kilian Bracher 2025-04-21 00:46:33 +02:00
parent 9cc314ad7c
commit 99eefa4283
Signed by: k.bracher
SSH Key Fingerprint: SHA256:mXpyZkK7RDiJ7qeHCKJX108woM0cl5TrCvNBJASu6lM
5 changed files with 98 additions and 70 deletions

View File

@ -52,16 +52,14 @@ bool log_is_level_enabled(log_level_t level) {
/* Main logging function */
void log_message(log_level_t level, const char *msg, ...) {
log_message_t log_msg;
log_msg.level = level;
log_msg.timestamp = HAL_GetTick();
log_message_t log_msg = {level, HAL_GetTick(), "\n", 0};
/* Format the message prefix (timestamp, log level) */
size_t prefix_len = 0;
size_t prefix_len = 1;
/* Add timestamp if configured */
if (PRINT_TIMESTAMP) {
prefix_len += snprintf(log_msg.message, MAX_MESSAGE_LENGTH, "[%lu] ", log_msg.timestamp);
prefix_len += snprintf(log_msg.message + prefix_len, MAX_MESSAGE_LENGTH, "[%lu] ", log_msg.timestamp);
}
/* Add log level name */

View File

@ -16,7 +16,7 @@
#include <stdbool.h>
/* Configuration */
#define MAX_MESSAGE_LENGTH 256
#define MAX_MESSAGE_LENGTH 384
#define USE_ANSI_ESCAPE_CODES true // if true, log messages will be colored according to their log level
#define PRINT_TIMESTAMP false // if true, timestamp (from HAL_GetTick) is printed before each log message
@ -70,6 +70,11 @@ void log_init_all_backends(void);
[[gnu::format(printf, 2, 3)]]
void log_message(log_level_t level, const char *msg, ...);
#ifdef LOG_PREFIX
#define log_message(level, fmt, ...) \
log_message(level, LOG_PREFIX fmt, ##__VA_ARGS__)
#endif
[[gnu::format(printf, 2, 3)]]
void log_message_cont(log_level_t level, const char *msg, ...);

View File

@ -11,6 +11,10 @@
#ifndef __SWO_LOG_H
#define __SWO_LOG_H
#ifdef SWO_LOG_PREFIX
#define LOG_PREFIX SWO_LOG_PREFIX
#endif
#include "log.h"
#include "swo_log_backend.h"

View File

@ -1,4 +1,5 @@
#include "imd_monitoring.h"
#include "log.h"
#include "main.h"
#include "soc_estimation.h"
#include "stm32h7xx_hal.h"
@ -8,49 +9,62 @@
#include "battery.h"
#define DEBUG_CHANNEL 1 // channel to output messages on
#include "swo_log.h"
#include "swo_log_backend.h"
void print_master_status() {
debug_clear_console();
auto backend = swo_log_get_backend();
debug_log(LOG_LEVEL_INFO, "------ AMS_Master on %s (%s), compiled at %s ------", COMMIT_BRANCH,
if (!backend->is_enabled(LOG_LEVEL_INFO)) {
return; // No need to print if the backend is not enabled for this log level
}
log_message_t log_msg = {};
#define swo_write(...) \
snprintf(log_msg.message, sizeof(log_msg.message), __VA_ARGS__); \
backend->write(&log_msg); \
// clear the console
backend->clear();
swo_write("------ AMS_Master on %s (%s), compiled at %s ------", COMMIT_BRANCH,
COMMIT_HASH, COMPILE_DATE);
debug_log(LOG_LEVEL_INFO, "\nGeneral:");
debug_log(LOG_LEVEL_INFO, " State: %s", TSStateToString(ts_state.current_state));
debug_log(LOG_LEVEL_INFO, " Target: %s", TSStateToString(ts_state.target_state));
debug_log(LOG_LEVEL_INFO, " Err Source: %s", ts_state.error_source == 0 ? "NONE" : (ts_state.error_source == 0b11 ? "SHUNT, SLAVE" : (ts_state.error_source == 0b01 ? "SHUNT" : "SLAVE")));
debug_log(LOG_LEVEL_INFO, " Err type: %s", ts_state.error_type == 0 ? "NONE" : (ts_state.error_type == 0x01 ? "SLAVE_TIMEOUT" : (ts_state.error_type == 0x02 ? "SLAVE_PANIC" : (ts_state.error_type == 0x03 ? "SHUNT_TIMEOUT" : (ts_state.error_type == 0x04 ? "SHUNT_OVERCURRENT" : (ts_state.error_type == 0x05 ? "SHUNT_OVERTEMP" : "UNKNOWN"))))));
debug_log(LOG_LEVEL_INFO, " HV active: %s", hv_active ? "YES" : "NO");
swo_write( "\nGeneral:");
swo_write( " State: %s", TSStateToString(ts_state.current_state));
swo_write( " Target: %s", TSStateToString(ts_state.target_state));
swo_write( " Err Source: %s", ts_state.error_source == 0 ? "NONE" : (ts_state.error_source == 0b11 ? "SHUNT, SLAVE" : (ts_state.error_source == 0b01 ? "SHUNT" : "SLAVE")));
swo_write(" Err type: %s", ts_state.error_type == 0 ? "NONE" : (ts_state.error_type == 0x01 ? "SLAVE_TIMEOUT" : (ts_state.error_type == 0x02 ? "SLAVE_PANIC" : (ts_state.error_type == 0x03 ? "SHUNT_TIMEOUT" : (ts_state.error_type == 0x04 ? "SHUNT_OVERCURRENT" : (ts_state.error_type == 0x05 ? "SHUNT_OVERTEMP" : "UNKNOWN"))))));
swo_write(" HV active: %s", hv_active ? "YES" : "NO");
debug_log(LOG_LEVEL_INFO, "\nRelay positions:");
debug_log(LOG_LEVEL_INFO, " SDC: %s", sdc_closed ? "CLOSED" : "OPEN");
debug_log(LOG_LEVEL_INFO, " Air-: %s", neg_air_closed ? "CLOSED" : "OPEN");
debug_log(LOG_LEVEL_INFO, " Air+: %s", pos_air_closed ? "CLOSED" : "OPEN");
debug_log(LOG_LEVEL_INFO, " Precharge: %s", precharge_closed ? "CLOSED" : "OPEN");
debug_log(LOG_LEVEL_INFO, " Precharge/Air+ sense: %s", pre_and_air_open ? "HIGH" : "LOW");
swo_write("\nRelay positions:");
swo_write(" SDC: %s", sdc_closed ? "CLOSED" : "OPEN");
swo_write(" Air-: %s", neg_air_closed ? "CLOSED" : "OPEN");
swo_write(" Air+: %s", pos_air_closed ? "CLOSED" : "OPEN");
swo_write(" Precharge: %s", precharge_closed ? "CLOSED" : "OPEN");
swo_write(" Precharge/Air+ sense: %s", pre_and_air_open ? "HIGH" : "LOW");
debug_log(LOG_LEVEL_INFO, "\nIMD data:");
debug_log(LOG_LEVEL_INFO, " State: %s", IMDStateToString(imd_data.state));
debug_log(LOG_LEVEL_INFO, " R_iso: %lu kOhm", imd_data.r_iso);
debug_log(LOG_LEVEL_INFO, " Frequency: %lu Hz", imd_data.freq);
debug_log(LOG_LEVEL_INFO, " Duty cycle: %lu %%", imd_data.duty_cycle);
debug_log(LOG_LEVEL_INFO, " Last high: %lu ms", imd_data.last_high);
debug_log(LOG_LEVEL_INFO, " OK: %s", imd_data.ok ? "YES" : "NO");
swo_write("\nIMD data:");
swo_write(" State: %s", IMDStateToString(imd_data.state));
swo_write(" R_iso: %lu kOhm", imd_data.r_iso);
swo_write(" Frequency: %lu Hz", imd_data.freq);
swo_write(" Duty cycle: %lu %%", imd_data.duty_cycle);
swo_write(" Last high: %lu ms", imd_data.last_high);
swo_write(" OK: %s", imd_data.ok ? "YES" : "NO");
debug_log(LOG_LEVEL_INFO, "\nShunt data:");
debug_log(LOG_LEVEL_INFO, " Voltage: %ld mV", shunt_data.voltage_bat);
debug_log(LOG_LEVEL_INFO, " Current: %ld mA", shunt_data.current);
debug_log(LOG_LEVEL_INFO, " Power: %ld W", shunt_data.power);
debug_log(LOG_LEVEL_INFO, " Energy: %ld Ws", shunt_data.energy);
debug_log(LOG_LEVEL_INFO, " Temp: %ld °C", shunt_data.busbartemp / 10);
debug_log(LOG_LEVEL_INFO, " Time delta: %lu ms", HAL_GetTick() - shunt_data.last_message);
swo_write("\nShunt data:");
swo_write(" Voltage: %ld mV", shunt_data.voltage_bat);
swo_write(" Current: %ld mA", shunt_data.current);
swo_write(" Power: %ld W", shunt_data.power);
swo_write(" Energy: %ld Ws", shunt_data.energy);
swo_write(" Temp: %ld °C", shunt_data.busbartemp / 10);
swo_write(" Time delta: %lu ms", HAL_GetTick() - shunt_data.last_message);
debug_log(LOG_LEVEL_INFO, "\nBattery data:");
debug_log(LOG_LEVEL_INFO, " Min/Max voltage: %d mV / %d mV", min_voltage, max_voltage);
debug_log(LOG_LEVEL_INFO, " Min/Max temp: %d °C / %d °C", min_temp, max_temp);
debug_log(LOG_LEVEL_INFO, " SoC: %.2f %%", current_soc);
debug_log(LOG_LEVEL_INFO, " Module data: Min V | Max V | Std Dev | Min T | Max T");
swo_write("\nBattery data:");
swo_write(" Min/Max voltage: %d mV / %d mV", min_voltage, max_voltage);
swo_write(" Min/Max temp: %d °C / %d °C", min_temp, max_temp);
swo_write(" SoC: %.2f %%", current_soc);
swo_write(" Module data: Min V | Max V | Std Dev | Min T | Max T");
auto max_std_dev = 0.0f;
for (size_t i = 0; i < N_BMS; i++) {
if (module_std_deviation[i] > max_std_dev) {
@ -62,20 +76,20 @@ void print_master_status() {
#define COLOR_MIN "\033[38;5;75m" //blue for min
#define COLOR_MAX "\033[38;5;203m" //red for max
#define COLOR_RESET "\033[0m"
debug_log(LOG_LEVEL_INFO, " %2zu: %s%5d mV%s | %s%5d mV%s | %s%.2f mV%s | %s%3d °C%s | %s%3d °C%s", i,
swo_write(" %2zu: %s%5d mV%s | %s%5d mV%s | %s%.2f mV%s | %s%3d °C%s | %s%3d °C%s", i,
(module_voltages[i].min == min_voltage) ? COLOR_MIN : "", (module_voltages[i].min), COLOR_RESET,
(module_voltages[i].max == max_voltage) ? COLOR_MAX : "", (module_voltages[i].max), COLOR_RESET,
(module_std_deviation[i] > max_std_dev) ? COLOR_MAX : "", module_std_deviation[i], COLOR_RESET,
(module_temps[i].min == min_temp) ? COLOR_MIN : "", (module_temps[i].min), COLOR_RESET,
(module_temps[i].max == max_temp) ? COLOR_MAX : "", (module_temps[i].max), COLOR_RESET);
#else
debug_log(LOG_LEVEL_INFO, " %2zu: %5d mV | %5d mV | %.2f mV | %3d °C | %3d °C", i,
swo_write(" %2zu: %5d mV | %5d mV | %.2f mV | %3d °C | %3d °C", i,
module_voltages[i].min, module_voltages[i].max,
module_std_deviation[i],
module_temps[i].min, module_temps[i].max);
#endif
}
debug_log(LOG_LEVEL_INFO, "\n------ Updated at %lu ------", HAL_GetTick());
swo_write("\n------ Updated at %lu ------", HAL_GetTick());
}

View File

@ -5,57 +5,71 @@
#include <string.h>
#define DEBUG_CHANNEL 2 // channel to output messages on
#include "swo_log.h"
#include "swo_log_backend.h"
void print_battery_info() {
debug_clear_console();
debug_log(LOG_LEVEL_INFO, "------ AMS_Master on %s (%s), compiled at %s ------\n", COMMIT_BRANCH,
auto backend = swo_log_get_backend();
if (!backend->is_enabled(LOG_LEVEL_INFO)) {
return; // No need to print if the backend is not enabled for this log level
}
log_message_t log_msg = {};
#define swo_write(...) \
snprintf(log_msg.message, sizeof(log_msg.message), __VA_ARGS__); \
backend->write(&log_msg); \
// clear the console
backend->clear();
swo_write("------ AMS_Master on %s (%s), compiled at %s ------\n", COMMIT_BRANCH,
COMMIT_HASH, COMPILE_DATE);
for (size_t i = 0; i < N_BMS; i++) {
debug_log(LOG_LEVEL_INFO, "Module %d status:", i);
debug_log(LOG_LEVEL_INFO, " BMS ID: 0x%08lx%08lx", (uint32_t)(modules[i].bmsID >> 32), (uint32_t)(modules[i].bmsID & 0xFFFFFFFF));
swo_write("Module %d status:", i);
swo_write(" BMS ID: 0x%08lx%08lx", (uint32_t)(modules[i].bmsID >> 32), (uint32_t)(modules[i].bmsID & 0xFFFFFFFF));
// Print cell voltages in 4x4 format
debug_log(LOG_LEVEL_INFO, " Cell voltages (mV):");
debug_log(LOG_LEVEL_INFO, " C0: %4d C1: %4d C2: %4d C3: %4d",
swo_write(" Cell voltages (mV):");
swo_write(" C0: %4d C1: %4d C2: %4d C3: %4d",
modules[i].cellVoltages[0], modules[i].cellVoltages[1],
modules[i].cellVoltages[2], modules[i].cellVoltages[3]);
debug_log(LOG_LEVEL_INFO, " C4: %4d C5: %4d C6: %4d C7: %4d",
swo_write(" C4: %4d C5: %4d C6: %4d C7: %4d",
modules[i].cellVoltages[4], modules[i].cellVoltages[5],
modules[i].cellVoltages[6], modules[i].cellVoltages[7]);
debug_log(LOG_LEVEL_INFO, " C8: %4d C9: %4d C10: %4d C11: %4d",
swo_write(" C8: %4d C9: %4d C10: %4d C11: %4d",
modules[i].cellVoltages[8], modules[i].cellVoltages[9],
modules[i].cellVoltages[10], modules[i].cellVoltages[11]);
debug_log(LOG_LEVEL_INFO, " C12: %4d C13: %4d C14: %4d C15: %4d",
swo_write(" C12: %4d C13: %4d C14: %4d C15: %4d",
modules[i].cellVoltages[12], modules[i].cellVoltages[13],
modules[i].cellVoltages[14], modules[i].cellVoltages[15]);
// Print GPIO values
debug_log(LOG_LEVEL_INFO, " GPIO voltages (mV):");
debug_log(LOG_LEVEL_INFO,
swo_write(" GPIO voltages (mV):");
swo_write(
" G0: %4d G1: %4d G2: %4d G3: %4d G4: %4d",
modules[i].auxVoltages[0], modules[i].auxVoltages[1],
modules[i].auxVoltages[2], modules[i].auxVoltages[3],
modules[i].auxVoltages[4]);
debug_log(LOG_LEVEL_INFO,
swo_write(
" G5: %4d G6: %4d G7: %4d G8: %4d G9: %4d",
modules[i].auxVoltages[5], modules[i].auxVoltages[6],
modules[i].auxVoltages[7], modules[i].auxVoltages[8],
modules[i].auxVoltages[9]);
// Print temperatures
debug_log(LOG_LEVEL_INFO, " GPIO as temperatures (°C):");
debug_log(LOG_LEVEL_INFO,
swo_write(" GPIO as temperatures (°C):");
swo_write(
" G0: %4d G1: %4d G2: %4d G3: %4d G4: %4d",
cellTemps[i][0], cellTemps[i][1], cellTemps[i][2],
cellTemps[i][3], cellTemps[i][4]);
debug_log(LOG_LEVEL_INFO,
swo_write(
" G5: %4d G6: %4d G7: %4d G8: %4d G9: %4d",
cellTemps[i][5], cellTemps[i][6], cellTemps[i][7],
cellTemps[i][8], cellTemps[i][9]);
debug_log(LOG_LEVEL_INFO,
swo_write(
" Internal temp: %d, VAnalog: %d, VDigital: %d, VRef: %d",
modules[i].internalDieTemp, modules[i].analogSupplyVoltage,
modules[i].digitalSupplyVoltage, modules[i].refVoltage);
@ -126,18 +140,11 @@ void print_battery_info() {
hasFlags = true;
}
debug_log(LOG_LEVEL_INFO, " Status flags: %s",
swo_write(" Status flags: %s",
hasFlags ? flagBuffer : "[none]");
debug_log(LOG_LEVEL_INFO, " Conversion counter: %d",
swo_write(" Conversion counter: %d",
modules[i].status.CCTS);
// Check for over/under voltage
if (modules[i].overVoltage || modules[i].underVoltage) {
debug_log(LOG_LEVEL_WARNING,
" Module %d voltage issues - OV: 0x%08lX, UV: 0x%08lX", i,
modules[i].overVoltage, modules[i].underVoltage);
}
}
debug_log(LOG_LEVEL_INFO, "\n------ Updated at %lu ------", HAL_GetTick());
swo_write("\n------ Updated at %lu ------", HAL_GetTick());
}