From 0cc91a7f7b820701ebe6b4fe43e6b11cf6c9be50 Mon Sep 17 00:00:00 2001 From: Robbe Derks Date: Tue, 13 Jun 2023 17:00:56 +0200 Subject: [PATCH] Logging (#1445) * try 1 * some fixes * fix some misra * first poc working * more things * more misra fixes * fix misra * add rate limiting * fix misra * add some unit tests through libpanda * add more tests and fix some stuff * fix misra again * add startup log hitl test * list * don't fail on wrong timestamps * improvements * fix tests * expected logs test? * not sure why this passed * oh, it doesn't reset * only show last few * guess at expected logs * needs this * ugh * reduce compiler warnings * adjust expected logs * this is correct * is it really 1? * min max * reduce spam in SPI test * some cleanup --- .github/workflows/test.yaml | 2 + __init__.py | 2 +- board/drivers/logging.h | 189 ++++++++++++++++++++++++++++ board/drivers/logging_definitions.h | 9 ++ board/drivers/rtc.h | 21 +--- board/drivers/rtc_definitions.h | 9 ++ board/fake_stm.h | 62 +++++++++ board/faults.h | 1 + board/flasher.h | 4 +- board/main.c | 5 + board/main_comms.h | 7 ++ board/stm32fx/llflash.h | 17 ++- board/stm32fx/stm32fx_config.h | 10 +- board/stm32h7/llflash.h | 21 ++-- board/stm32h7/stm32h7_config.h | 10 +- python/__init__.py | 31 ++++- tests/hitl/0_dfu.py | 2 + tests/hitl/1_program.py | 3 + tests/hitl/2_health.py | 16 ++- tests/hitl/8_spi.py | 4 +- tests/hitl/conftest.py | 19 +++ tests/libpanda/libpanda_py.py | 36 ++++++ tests/libpanda/panda.c | 11 ++ tests/logging/test.sh | 4 + tests/logging/test_logging.py | 77 ++++++++++++ 25 files changed, 525 insertions(+), 47 deletions(-) create mode 100644 board/drivers/logging.h create mode 100644 board/drivers/logging_definitions.h create mode 100644 board/drivers/rtc_definitions.h create mode 100755 tests/logging/test.sh create mode 100755 tests/logging/test_logging.py diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml index 20044cba..df7ca751 100644 --- a/.github/workflows/test.yaml +++ b/.github/workflows/test.yaml @@ -61,6 +61,8 @@ jobs: run: $RUN "scons -j4" - name: Test communication protocols run: $RUN "cd tests/usbprotocol && ./test.sh" + - name: Test logging + run: $RUN "cd tests/logging && ./test.sh" safety: name: safety diff --git a/__init__.py b/__init__.py index d3a558f4..21e35b9e 100644 --- a/__init__.py +++ b/__init__.py @@ -1,5 +1,5 @@ from .python.constants import McuType, BASEDIR, FW_PATH # noqa: F401 from .python.serial import PandaSerial # noqa: F401 from .python import (Panda, PandaDFU, # noqa: F401 - pack_can_buffer, unpack_can_buffer, calculate_checksum, + pack_can_buffer, unpack_can_buffer, calculate_checksum, unpack_log, DLC_TO_LEN, LEN_TO_DLC, ALTERNATIVE_EXPERIENCE, USBPACKET_MAX_SIZE, CANPACKET_HEAD_SIZE) diff --git a/board/drivers/logging.h b/board/drivers/logging.h new file mode 100644 index 00000000..6d21c87c --- /dev/null +++ b/board/drivers/logging.h @@ -0,0 +1,189 @@ + +#include "logging_definitions.h" + +#define BANK_SIZE 0x20000U +#define BANK_LOG_CAPACITY (BANK_SIZE / sizeof(log_t)) +#define TOTAL_LOG_CAPACITY (BANK_LOG_CAPACITY * 2U) + +#define LOGGING_MAX_LOGS_PER_MINUTE 10U + +struct logging_state_t { + uint16_t read_index; + uint16_t write_index; + uint16_t last_id; + + uint8_t rate_limit_counter; + uint8_t rate_limit_log_count; +}; +struct logging_state_t log_state = { 0 }; +log_t *log_arr = (log_t *) LOGGING_FLASH_BASE_A; + +uint16_t logging_next_id(uint16_t id) { + return (id + 1U) % 0xFFFEU; +} + +uint16_t logging_next_index(uint16_t index) { + return (index + 1U) % TOTAL_LOG_CAPACITY; +} + +void logging_erase_bank(uint8_t flash_sector) { + print("erasing sector "); puth(flash_sector); print("\n"); + flash_unlock(); + if (!flash_erase_sector(flash_sector)) { + print("failed to erase sector "); puth(flash_sector); print("\n"); + } + flash_lock(); +} + +void logging_erase(void) { + logging_erase_bank(LOGGING_FLASH_SECTOR_A); + logging_erase_bank(LOGGING_FLASH_SECTOR_B); + log_state.read_index = 0U; + log_state.write_index = 0U; +} + +void logging_find_read_index(void) { + // Figure out the read index by the last empty slot + log_state.read_index = 0xFFFFU; + for (uint16_t i = 0U; i < TOTAL_LOG_CAPACITY; i++) { + if (log_arr[i].id == 0xFFFFU) { + log_state.read_index = logging_next_index(i); + } + } +} + +void logging_init(void) { + COMPILE_TIME_ASSERT(sizeof(log_t) == 64U); + COMPILE_TIME_ASSERT((LOGGING_FLASH_BASE_A + BANK_SIZE) == LOGGING_FLASH_BASE_B); + + // Make sure all empty-ID logs are fully empty + log_t empty_log; + (void) memset(&empty_log, 0xFF, sizeof(log_t)); + + for (uint16_t i = 0U; i < TOTAL_LOG_CAPACITY; i++) { + if ((log_arr[i].id == 0xFFFFU) && (memcmp(&log_arr[i], &empty_log, sizeof(log_t)) != 0)) { + logging_erase(); + break; + } + } + + logging_find_read_index(); + + // At initialization, the read index should always be at the beginning of a bank + // If not, clean slate + if ((log_state.read_index != 0U) && (log_state.read_index != BANK_LOG_CAPACITY)) { + logging_erase(); + } + + // Figure out the write index + log_state.write_index = log_state.read_index; + log_state.last_id = log_arr[log_state.write_index].id - 1U; + for (uint16_t i = 0U; i < TOTAL_LOG_CAPACITY; i++) { + bool done = false; + if (log_arr[log_state.write_index].id == 0xFFFFU) { + // Found the first empty slot after the read pointer + done = true; + } else if (log_arr[log_state.write_index].id != logging_next_id(log_state.last_id)) { + // Discontinuity in the index, shouldn't happen! + logging_erase(); + done = true; + } else { + log_state.last_id = log_arr[log_state.write_index].id; + log_state.write_index = logging_next_index(log_state.write_index); + } + + if (done) { + break; + } + } + + // Reset rate limit + log_state.rate_limit_counter = 0U; + log_state.rate_limit_log_count = 0U; +} + +// Call at 1Hz +void logging_tick(void) { + flush_write_buffer(); + + log_state.rate_limit_counter++; + if (log_state.rate_limit_counter >= 60U) { + log_state.rate_limit_counter = 0U; + log_state.rate_limit_log_count = 0U; + } +} + +void log(const char* msg){ + if (log_state.rate_limit_log_count < LOGGING_MAX_LOGS_PER_MINUTE) { + ENTER_CRITICAL(); + log_t new_log = {0}; + new_log.id = logging_next_id(log_state.last_id); + log_state.last_id = new_log.id; + new_log.uptime = uptime_cnt; + if (current_board->has_rtc_battery) { + new_log.timestamp = rtc_get_time(); + } + + uint8_t i = 0U; + for (const char *in = msg; *in; in++) { + new_log.msg[i] = *in; + i++; + if (i >= sizeof(new_log.msg)) { + print("log message too long\n"); + break; + } + } + + // If we are at the beginning of a bank, erase it first and move the read pointer if needed + switch (log_state.write_index) { + case ((2U * BANK_LOG_CAPACITY) - 1U): + logging_erase_bank(LOGGING_FLASH_SECTOR_A); + if ((log_state.read_index < BANK_LOG_CAPACITY)) { + log_state.read_index = BANK_LOG_CAPACITY; + } + break; + case (BANK_LOG_CAPACITY - 1U): + // beginning to write in bank B + logging_erase_bank(LOGGING_FLASH_SECTOR_B); + if ((log_state.read_index > BANK_LOG_CAPACITY)) { + log_state.read_index = 0U; + } + break; + default: + break; + } + + // Write! + void *addr = &log_arr[log_state.write_index]; + uint32_t data[sizeof(log_t) / sizeof(uint32_t)]; + (void) memcpy(data, &new_log, sizeof(log_t)); + + flash_unlock(); + for (uint8_t j = 0U; j < sizeof(log_t) / sizeof(uint32_t); j++) { + flash_write_word(&((uint32_t *) addr)[j], data[j]); + } + flash_lock(); + + // Update the write index + log_state.write_index = logging_next_index(log_state.write_index); + EXIT_CRITICAL(); + + log_state.rate_limit_log_count++; + } else { + fault_occurred(FAULT_LOGGING_RATE_LIMIT); + } +} + +uint8_t logging_read(uint8_t *buffer) { + uint8_t ret = 0U; + if ((log_arr[log_state.read_index].id != 0xFFFFU) && (log_state.read_index != log_state.write_index)) { + // Read the log + (void) memcpy(buffer, &log_arr[log_state.read_index], sizeof(log_t)); + + // Update the read index + log_state.read_index = logging_next_index(log_state.read_index); + + ret = sizeof(log_t); + } + return ret; +} diff --git a/board/drivers/logging_definitions.h b/board/drivers/logging_definitions.h new file mode 100644 index 00000000..9c1bc02e --- /dev/null +++ b/board/drivers/logging_definitions.h @@ -0,0 +1,9 @@ + +// Flash is writable in 32-byte lines, this struct is designed to fit in two lines. +// This also matches the USB transfer size. +typedef struct __attribute__((packed)) log_t { + uint16_t id; + timestamp_t timestamp; + uint32_t uptime; + char msg[50]; +} log_t; diff --git a/board/drivers/rtc.h b/board/drivers/rtc.h index df121e3e..231d88f2 100644 --- a/board/drivers/rtc.h +++ b/board/drivers/rtc.h @@ -1,14 +1,7 @@ -#define YEAR_OFFSET 2000U -typedef struct __attribute__((packed)) timestamp_t { - uint16_t year; - uint8_t month; - uint8_t day; - uint8_t weekday; - uint8_t hour; - uint8_t minute; - uint8_t second; -} timestamp_t; +#include "rtc_definitions.h" + +#define YEAR_OFFSET 2000U uint8_t to_bcd(uint16_t value){ return (((value / 10U) & 0x0FU) << 4U) | ((value % 10U) & 0x0FU); @@ -50,14 +43,6 @@ void rtc_set_time(timestamp_t time){ timestamp_t rtc_get_time(void){ timestamp_t result; - // Init with zero values in case there is no RTC running - result.year = 0U; - result.month = 0U; - result.day = 0U; - result.weekday = 0U; - result.hour = 0U; - result.minute = 0U; - result.second = 0U; // Wait until the register sync flag is set while((RTC->ISR & RTC_ISR_RSF) == 0){} diff --git a/board/drivers/rtc_definitions.h b/board/drivers/rtc_definitions.h new file mode 100644 index 00000000..d308eb74 --- /dev/null +++ b/board/drivers/rtc_definitions.h @@ -0,0 +1,9 @@ +typedef struct __attribute__((packed)) timestamp_t { + uint16_t year; + uint8_t month; + uint8_t day; + uint8_t weekday; + uint8_t hour; + uint8_t minute; + uint8_t second; +} timestamp_t; diff --git a/board/fake_stm.h b/board/fake_stm.h index b73a4e89..66baa1d3 100644 --- a/board/fake_stm.h +++ b/board/fake_stm.h @@ -2,8 +2,10 @@ #include #include #include +#include #include "utils.h" +#include "drivers/rtc_definitions.h" #define CANFD #define ALLOW_DEBUG @@ -31,3 +33,63 @@ uint32_t microsecond_timer_get(void); uint32_t microsecond_timer_get(void) { return MICROSECOND_TIMER->CNT; } + +// Register functions +void register_set_bits(volatile uint32_t *addr, uint32_t val) {} + +// RTC +timestamp_t rtc_get_time() { + timestamp_t result; + result.year = 1996; + result.month = 4; + result.day = 23; + result.weekday = 2; + result.hour = 4; + result.minute = 20; + result.second = 20; + return result; +} + +// Logging and flash +uint8_t fake_logging_bank[0x40000] __attribute__ ((aligned (4))); +#define LOGGING_FLASH_BASE_A (&fake_logging_bank[0]) +#define LOGGING_FLASH_BASE_B (&fake_logging_bank[0x20000]) +#define LOGGING_FLASH_SECTOR_A 5 +#define LOGGING_FLASH_SECTOR_B 6 + +bool flash_locked = true; +void flash_unlock(void) { + flash_locked = false; +} +void flash_lock(void) { + flash_locked = true; +} + +void *memset(void *str, int c, unsigned int n); + +bool flash_erase_sector(uint8_t sector) { + if (flash_locked) { + return false; + } + + switch (sector) { + case LOGGING_FLASH_SECTOR_A: + memset(LOGGING_FLASH_BASE_A, 0xFF, sizeof(fake_logging_bank)/2); + return true; + case LOGGING_FLASH_SECTOR_B: + memset(LOGGING_FLASH_BASE_B, 0xFF, sizeof(fake_logging_bank)/2); + return true; + default: + return false; + } +} + +void flash_write_word(void *prog_ptr, uint32_t data) { + if (flash_locked || prog_ptr < (void *) LOGGING_FLASH_BASE_A || prog_ptr >= (void *) (LOGGING_FLASH_BASE_A + sizeof(fake_logging_bank))) { + return; + } + + *(uint32_t *)prog_ptr = data; +} + +void flush_write_buffer(void) {} \ No newline at end of file diff --git a/board/faults.h b/board/faults.h index 6c6bef47..a741ea1c 100644 --- a/board/faults.h +++ b/board/faults.h @@ -30,6 +30,7 @@ #define FAULT_INTERRUPT_RATE_UART_7 (1U << 24) #define FAULT_SIREN_MALFUNCTION (1U << 25) #define FAULT_HEARTBEAT_LOOP_WATCHDOG (1U << 26) +#define FAULT_LOGGING_RATE_LIMIT (1U << 27) // Permanent faults #define PERMANENT_FAULTS 0U diff --git a/board/flasher.h b/board/flasher.h index bcd98daf..351a8999 100644 --- a/board/flasher.h +++ b/board/flasher.h @@ -1,6 +1,5 @@ // flasher state variables uint32_t *prog_ptr = NULL; -bool unlocked = false; void spi_init(void); @@ -33,13 +32,12 @@ int comms_control_handler(ControlPacket_t *req, uint8_t *resp) { resp[1] = 0xff; } current_board->set_led(LED_GREEN, 1); - unlocked = true; prog_ptr = (uint32_t *)APP_START_ADDRESS; break; // **** 0xb2: erase sector case 0xb2: sec = req->param1; - if (flash_erase_sector(sec, unlocked)) { + if (flash_erase_sector(sec)) { resp[1] = 0xff; } break; diff --git a/board/main.c b/board/main.c index b8831c9d..ad92d721 100644 --- a/board/main.c +++ b/board/main.c @@ -6,6 +6,7 @@ #include "drivers/gmlan_alt.h" #include "drivers/kline_init.h" #include "drivers/simple_watchdog.h" +#include "drivers/logging.h" #include "early_init.h" #include "provision.h" @@ -182,6 +183,7 @@ void tick_handler(void) { // tick drivers at 1Hz harness_tick(); + logging_tick(); const bool recent_heartbeat = heartbeat_counter == 0U; current_board->board_tick(check_started(), usb_enumerated, recent_heartbeat, ((harness.status != previous_harness_status) && (harness.status != HARNESS_STATUS_NC))); @@ -328,6 +330,7 @@ int main(void) { peripherals_init(); detect_board_type(); adc_init(); + logging_init(); // print hello print("\n\n\n************************ MAIN START ************************\n"); @@ -347,6 +350,8 @@ int main(void) { // panda has an FPU, let's use it! enable_fpu(); + log("main start"); + if (current_board->has_gps) { uart_init(&uart_ring_gps, 9600); } else { diff --git a/board/main_comms.h b/board/main_comms.h index b58ebd1d..19e642bc 100644 --- a/board/main_comms.h +++ b/board/main_comms.h @@ -478,6 +478,13 @@ int comms_control_handler(ControlPacket_t *req, uint8_t *resp) { UNUSED(ret); } break; + // *** 0xfd: read logs + case 0xfd: + if (req->param1 == 1U) { + logging_find_read_index(); + } + resp_len = logging_read(resp); + break; default: print("NO HANDLER "); puth(req->request); diff --git a/board/stm32fx/llflash.h b/board/stm32fx/llflash.h index 61adcd45..7ae14ca5 100644 --- a/board/stm32fx/llflash.h +++ b/board/stm32fx/llflash.h @@ -7,22 +7,27 @@ void flash_unlock(void) { FLASH->KEYR = 0xCDEF89AB; } -bool flash_erase_sector(uint8_t sector, bool unlocked) { +void flash_lock(void) { + FLASH->CR |= FLASH_CR_LOCK; +} + +bool flash_erase_sector(uint16_t sector) { // don't erase the bootloader(sector 0) - if (sector != 0 && sector < 12 && unlocked) { + bool ret = false; + if ((sector != 0U) && (sector < 12U) && (!flash_is_locked())) { FLASH->CR = (sector << 3) | FLASH_CR_SER; FLASH->CR |= FLASH_CR_STRT; - while (FLASH->SR & FLASH_SR_BSY); - return true; + while ((FLASH->SR & FLASH_SR_BSY) != 0U); + ret = true; } - return false; + return ret; } void flash_write_word(void *prog_ptr, uint32_t data) { uint32_t *pp = prog_ptr; FLASH->CR = FLASH_CR_PSIZE_1 | FLASH_CR_PG; *pp = data; - while (FLASH->SR & FLASH_SR_BSY); + while ((FLASH->SR & FLASH_SR_BSY) != 0U); } void flush_write_buffer(void) { } diff --git a/board/stm32fx/stm32fx_config.h b/board/stm32fx/stm32fx_config.h index a7323974..8bf54965 100644 --- a/board/stm32fx/stm32fx_config.h +++ b/board/stm32fx/stm32fx_config.h @@ -38,6 +38,11 @@ #define PROVISION_CHUNK_ADDRESS 0x1FFF79E0U #define DEVICE_SERIAL_NUMBER_ADDRESS 0x1FFF79C0U +#define LOGGING_FLASH_SECTOR_A 10U +#define LOGGING_FLASH_SECTOR_B 11U +#define LOGGING_FLASH_BASE_A 0x080C0000U +#define LOGGING_FLASH_BASE_B 0x080E0000U + #include "can_definitions.h" #include "comms_definitions.h" @@ -65,6 +70,7 @@ #include "stm32fx/board.h" #include "stm32fx/clock.h" #include "drivers/watchdog.h" +#include "stm32fx/llflash.h" #if defined(PANDA) || defined(BOOTSTUB) #include "drivers/spi.h" @@ -80,9 +86,7 @@ #include "stm32fx/llexti.h" #endif -#ifdef BOOTSTUB - #include "stm32fx/llflash.h" -#else +#ifndef BOOTSTUB #include "stm32fx/llbxcan.h" #endif diff --git a/board/stm32h7/llflash.h b/board/stm32h7/llflash.h index b95011a9..ece69c5c 100644 --- a/board/stm32h7/llflash.h +++ b/board/stm32h7/llflash.h @@ -7,27 +7,32 @@ void flash_unlock(void) { FLASH->KEYR1 = 0xCDEF89AB; } -bool flash_erase_sector(uint8_t sector, bool unlocked) { +void flash_lock(void) { + FLASH->CR1 |= FLASH_CR_LOCK; +} + +bool flash_erase_sector(uint16_t sector) { // don't erase the bootloader(sector 0) - if (sector != 0 && sector < 8 && unlocked) { + bool ret = false; + if ((sector != 0U) && (sector < 8U) && (!flash_is_locked())) { FLASH->CR1 = (sector << 8) | FLASH_CR_SER; FLASH->CR1 |= FLASH_CR_START; - while (FLASH->SR1 & FLASH_SR_QW); - return true; + while ((FLASH->SR1 & FLASH_SR_QW) != 0U); + ret = true; } - return false; + return ret; } void flash_write_word(void *prog_ptr, uint32_t data) { uint32_t *pp = prog_ptr; FLASH->CR1 |= FLASH_CR_PG; *pp = data; - while (FLASH->SR1 & FLASH_SR_QW); + while ((FLASH->SR1 & FLASH_SR_QW) != 0U); } void flush_write_buffer(void) { - if (FLASH->SR1 & FLASH_SR_WBNE) { + if ((FLASH->SR1 & FLASH_SR_WBNE) != 0U) { FLASH->CR1 |= FLASH_CR_FW; - while (FLASH->SR1 & FLASH_CR_FW); + while ((FLASH->SR1 & FLASH_CR_FW) != 0U); } } diff --git a/board/stm32h7/stm32h7_config.h b/board/stm32h7/stm32h7_config.h index 41ae768a..85e349e3 100644 --- a/board/stm32h7/stm32h7_config.h +++ b/board/stm32h7/stm32h7_config.h @@ -46,6 +46,11 @@ separate IRQs for RX and TX. #define PROVISION_CHUNK_ADDRESS 0x080FFFE0U #define DEVICE_SERIAL_NUMBER_ADDRESS 0x080FFFC0U +#define LOGGING_FLASH_SECTOR_A 5U +#define LOGGING_FLASH_SECTOR_B 6U +#define LOGGING_FLASH_BASE_A 0x080A0000U +#define LOGGING_FLASH_BASE_B 0x080C0000U + #include "can_definitions.h" #include "comms_definitions.h" @@ -67,6 +72,7 @@ separate IRQs for RX and TX. #include "stm32h7/interrupt_handlers.h" #include "drivers/timers.h" #include "drivers/watchdog.h" +#include "stm32h7/llflash.h" #if !defined(BOOTSTUB) && defined(PANDA) #include "drivers/uart.h" @@ -80,9 +86,7 @@ separate IRQs for RX and TX. #include "stm32h7/llexti.h" #endif -#ifdef BOOTSTUB - #include "stm32h7/llflash.h" -#else +#ifndef BOOTSTUB #include "stm32h7/llfdcan.h" #endif diff --git a/python/__init__.py b/python/__init__.py index ab095c0b..112857e4 100644 --- a/python/__init__.py +++ b/python/__init__.py @@ -122,6 +122,24 @@ def ensure_can_health_packet_version(fn): return fn(self, *args, **kwargs) return wrapper +def parse_timestamp(dat): + a = struct.unpack("HBBBBBB", dat) + if a[0] == 0: + return None + + try: + return datetime.datetime(a[0], a[1], a[2], a[4], a[5], a[6]) + except ValueError: + return None + +def unpack_log(dat): + return { + 'id': struct.unpack("H", dat[:2])[0], + 'timestamp': parse_timestamp(dat[2:10]), + 'uptime': struct.unpack("I", dat[10:14])[0], + 'msg': bytes(dat[14:]).decode('utf-8', 'ignore').strip('\x00'), + } + class ALTERNATIVE_EXPERIENCE: DEFAULT = 0 DISABLE_DISENGAGE_ON_GAS = 1 @@ -941,8 +959,7 @@ class Panda: def get_datetime(self): dat = self._handle.controlRead(Panda.REQUEST_IN, 0xa0, 0, 0, 8) - a = struct.unpack("HBBBBBB", dat) - return datetime.datetime(a[0], a[1], a[2], a[4], a[5], a[6]) + return parse_timestamp(dat) # ****************** Timer ***************** def get_microsecond_timer(self): @@ -973,3 +990,13 @@ class Panda: # ****************** Debug ***************** def set_green_led(self, enabled): self._handle.controlWrite(Panda.REQUEST_OUT, 0xf7, int(enabled), 0, b'') + + # ****************** Logging ***************** + def get_logs(self, get_all=False): + logs = [] + dat = self._handle.controlRead(Panda.REQUEST_IN, 0xfd, 1 if get_all else 0, 0, 0x40) + while len(dat) > 0: + if len(dat) == 0x40: + logs.append(unpack_log(dat)) + dat = self._handle.controlRead(Panda.REQUEST_IN, 0xfd, 0, 0, 0x40) + return logs diff --git a/tests/hitl/0_dfu.py b/tests/hitl/0_dfu.py index a8afa24a..f3b8ae04 100644 --- a/tests/hitl/0_dfu.py +++ b/tests/hitl/0_dfu.py @@ -4,6 +4,7 @@ import random from panda import Panda, PandaDFU from panda.python.spi import SpiDevice +@pytest.mark.expected_logs(1) def test_dfu(p): app_mcu_type = p.get_mcu_type() dfu_serial = p.get_dfu_serial() @@ -22,6 +23,7 @@ def test_dfu(p): p.reconnect() +@pytest.mark.expected_logs(1) @pytest.mark.test_panda_types((Panda.HW_TYPE_TRES, )) def test_dfu_with_spam(p): dfu_serial = p.get_dfu_serial() diff --git a/tests/hitl/1_program.py b/tests/hitl/1_program.py index 7d957bf4..b051636f 100644 --- a/tests/hitl/1_program.py +++ b/tests/hitl/1_program.py @@ -12,6 +12,7 @@ def check_signature(p): # TODO: make more comprehensive bootstub tests and run on a few production ones + current # TODO: also test release-signed app @pytest.mark.execution_timeout(30) +@pytest.mark.expected_logs(1, 2) def test_a_known_bootstub(p): """ Test that compiled app can work with known production bootstub @@ -58,11 +59,13 @@ def test_a_known_bootstub(p): assert not p.bootstub @pytest.mark.execution_timeout(25) +@pytest.mark.expected_logs(1) def test_b_recover(p): assert p.recover(timeout=30) check_signature(p) @pytest.mark.execution_timeout(25) +@pytest.mark.expected_logs(3) def test_c_flash(p): # test flash from bootstub serial = p._serial diff --git a/tests/hitl/2_health.py b/tests/hitl/2_health.py index 5ab6008d..1fe0b5a1 100644 --- a/tests/hitl/2_health.py +++ b/tests/hitl/2_health.py @@ -5,7 +5,7 @@ from panda import Panda from panda_jungle import PandaJungle # pylint: disable=import-error from panda.tests.hitl.conftest import PandaGroup - +@pytest.mark.expected_logs(1) def test_ignition(p, panda_jungle): # Set harness orientation to #2, since the ignition line is on the wrong SBU bus :/ panda_jungle.set_harness_orientation(PandaJungle.HARNESS_ORIENTATION_2) @@ -71,6 +71,7 @@ def test_voltage(p): assert ((voltage > 11000) and (voltage < 13000)) time.sleep(0.1) +@pytest.mark.expected_logs(1) def test_hw_type(p): """ hw type should be same in bootstub as application @@ -123,3 +124,16 @@ def test_microsecond_timer(p): time_diff = (end_time - start_time) / 1e6 assert 0.98 < time_diff < 1.02, f"Timer not running at the correct speed! (got {time_diff:.2f}s instead of 1.0s)" + +@pytest.mark.expected_logs(1) +def test_logging(p): + p.reset() + + logs = p.get_logs(True) + assert len(logs) > 0 + assert len(p.get_logs()) == 0 + + # we assume the start log is relatively recent + start_logs = list(filter(lambda x: x['msg'] == 'main start', logs[-5:])) + assert len(start_logs) > 0 + assert start_logs[0]['uptime'] < 2 diff --git a/tests/hitl/8_spi.py b/tests/hitl/8_spi.py index 3d8a33b0..c4a4502e 100644 --- a/tests/hitl/8_spi.py +++ b/tests/hitl/8_spi.py @@ -48,11 +48,11 @@ class TestSpi: for _ in range(10): ep = random.randint(4, 20) with pytest.raises(PandaSpiNackResponse): - p._handle.bulkRead(ep, random.randint(1, 1000), timeout=50) + p._handle.bulkRead(ep, random.randint(1, 1000), timeout=35) self._ping(mocker, p) with pytest.raises(PandaSpiNackResponse): - p._handle.bulkWrite(ep, b"abc", timeout=50) + p._handle.bulkWrite(ep, b"abc", timeout=35) self._ping(mocker, p) diff --git a/tests/hitl/conftest.py b/tests/hitl/conftest.py index 0ebef622..dbe33c7f 100644 --- a/tests/hitl/conftest.py +++ b/tests/hitl/conftest.py @@ -86,6 +86,9 @@ def pytest_configure(config): config.addinivalue_line( "markers", "panda_expect_can_error: mark test to ignore CAN health errors" ) + config.addinivalue_line( + "markers", "expected_logs(amount, ...): mark test to expect a certain amount of panda logs" + ) def pytest_collection_modifyitems(items): for item in items: @@ -130,6 +133,8 @@ def func_fixture_panda(request, module_panda): # TODO: reset is slow (2+ seconds) p.reset() + logs = p.get_logs() + last_log_id = logs[-1]['id'] if len(logs) > 0 else 0 # Run test yield p @@ -154,6 +159,20 @@ def func_fixture_panda(request, module_panda): assert p.health()['faults'] == 0 assert p.health()['fault_status'] == 0 + # Make sure that there are no unexpected logs + min_expected_logs = 0 + max_expected_logs = 0 + mark = request.node.get_closest_marker('expected_logs') + if mark: + assert len(mark.args) > 0, "Missing expected logs argument in mark" + min_expected_logs = mark.args[0] + max_expected_logs = mark.args[1] if len(mark.args) > 1 else min_expected_logs + + logs.extend(p.get_logs(True)) + log_id = logs[-1]['id'] if len(logs) > 0 else last_log_id + + assert min_expected_logs <= ((log_id - last_log_id) % 0xFFFE) <= max_expected_logs, f"Unexpected amount of logs. Last 5: {logs[-5:]}" + # Check for SPI errors #assert p.health()['spi_checksum_error_count'] == 0 diff --git a/tests/libpanda/libpanda_py.py b/tests/libpanda/libpanda_py.py index 2beec5cc..b95ceb9f 100644 --- a/tests/libpanda/libpanda_py.py +++ b/tests/libpanda/libpanda_py.py @@ -54,6 +54,34 @@ void comms_can_reset(void); uint32_t can_slots_empty(can_ring *q); """) +ffi.cdef(""" + typedef struct timestamp_t { + uint16_t year; + uint8_t month; + uint8_t day; + uint8_t weekday; + uint8_t hour; + uint8_t minute; + uint8_t second; + } timestamp_t; + + typedef struct { + uint16_t id; + timestamp_t timestamp; + uint32_t uptime; + char msg[50]; + } log_t; + + extern uint32_t *logging_bank; + extern uint32_t logging_bank_size; + extern uint32_t logging_rate_limit; + + void logging_init(void); + void logging_tick(void); + void log(const char* msg); + uint8_t logging_read(uint8_t *buffer); +""") + setup_safety_helpers(ffi) class CANPacket: @@ -73,6 +101,14 @@ class Panda(PandaSafety): def safety_fwd_hook(self, bus_num: int, addr: int) -> int: ... def set_safety_hooks(self, mode: int, param: int) -> int: ... + # logging + def logging_init(self) -> None: ... + def logging_tick(self) -> None: ... + def log(self, msg: bytearray) -> None: ... + def logging_read(self, buffer: bytearray) -> int: ... + logging_bank: bytearray + logging_bank_size: int + logging_rate_limit: int libpanda: Panda = ffi.dlopen(libpanda_fn) diff --git a/tests/libpanda/panda.c b/tests/libpanda/panda.c index 8efb6de4..050e102a 100644 --- a/tests/libpanda/panda.c +++ b/tests/libpanda/panda.c @@ -19,6 +19,13 @@ void can_tx_comms_resume_spi(void) { }; #include "safety.h" #include "main_declarations.h" #include "drivers/can_common.h" +#include "drivers/logging.h" + +// Board +const board fake_board = { + .has_rtc_battery = true, +}; +const board *current_board = &fake_board; can_ring *rx_q = &can_rx_q; can_ring *txgmlan_q = &can_txgmlan_q; @@ -26,6 +33,10 @@ can_ring *tx1_q = &can_tx1_q; can_ring *tx2_q = &can_tx2_q; can_ring *tx3_q = &can_tx3_q; +uint32_t *logging_bank = (uint32_t *) fake_logging_bank; +uint32_t logging_bank_size = sizeof(fake_logging_bank); +uint32_t logging_rate_limit = LOGGING_MAX_LOGS_PER_MINUTE; + #include "comms_definitions.h" #include "can_comms.h" diff --git a/tests/logging/test.sh b/tests/logging/test.sh new file mode 100755 index 00000000..9e084772 --- /dev/null +++ b/tests/logging/test.sh @@ -0,0 +1,4 @@ +#!/usr/bin/env bash +set -e + +python -m unittest discover . diff --git a/tests/logging/test_logging.py b/tests/logging/test_logging.py new file mode 100755 index 00000000..dc24f8b2 --- /dev/null +++ b/tests/logging/test_logging.py @@ -0,0 +1,77 @@ +#!/usr/bin/env python3 + +import random +import unittest +import datetime + +from panda import unpack_log +from panda.tests.libpanda import libpanda_py + +lpp = libpanda_py.libpanda + +class TestLogging(unittest.TestCase): + def setUp(self): + # Clear buffer and setup state + for i in range(lpp.logging_bank_size // 4): + lpp.logging_bank[i] = 0xFFFFFFFF + lpp.logging_init() + + def _get_logs(self): + logs = [] + while True: + log = libpanda_py.ffi.new("uint8_t[64]") + if lpp.logging_read(log) == 0: + break + logs.append(log) + return logs + + def _log(self, msg): + lpp.log(libpanda_py.ffi.new("char[]", msg.encode("utf-8"))) + + def test_random_buffer_init(self): + for i in range(lpp.logging_bank_size // 4): + lpp.logging_bank[i] = random.randint(0, 0xFFFFFFFF) + + lpp.logging_init() + + for i in range(lpp.logging_bank_size // 4): + assert lpp.logging_bank[i] == 0xFFFFFFFF + self.assertEqual(lpp.logging_read(libpanda_py.ffi.new("uint8_t[64]")), 0) + + def test_rate_limit(self): + for _ in range(lpp.logging_rate_limit + 5): + self._log("test") + self.assertEqual(len(self._get_logs()), lpp.logging_rate_limit) + self.assertEqual(len(self._get_logs()), 0) + + for _ in range(62): + lpp.logging_tick() + + for _ in range(lpp.logging_rate_limit + 5): + self._log("test") + + self.assertEqual(len(self._get_logs()), lpp.logging_rate_limit) + self.assertEqual(len(self._get_logs()), 0) + + def test_logging(self): + msg = "testing 123" + self._log(msg) + logs = self._get_logs() + self.assertEqual(len(logs), 1) + log = unpack_log(bytes(logs[0])) + self.assertEqual(log['msg'], msg) + self.assertEqual(log['uptime'], 0) + self.assertEqual(log['id'], 1) + self.assertEqual(log['timestamp'], datetime.datetime(1996, 4, 23, 4, 20, 20)) + + def test_bank_overflow(self): + for i in range(1, 10000): + self._log("test") + + if i % 5 == 0: + lpp.logging_init() + expected_messages = (i % 2048) + (2048 if i >= 2048 else 0) + self.assertEqual(len(self._get_logs()), expected_messages) + +if __name__ == "__main__": + unittest.main() \ No newline at end of file