Commit 17c7c61e authored by schneider's avatar schneider
Browse files

feat(ble): write HCI layer log file

Adds an option to write a btsnoop compatible log file containing BLE
traffic. A new file is created after each boot if BLE is activated and
the `ble_log_enable` option is set in `card10.cfg`. The last 10 logs are
kept via log rotation.
parent f0807c24
...@@ -34,12 +34,14 @@ Float A single-precision (32-bit) floating-point number in base 10. Example: ...@@ -34,12 +34,14 @@ Float A single-precision (32-bit) floating-point number in base 10. Example:
Supported options Supported options
----------------- -----------------
=============== ========== =========== ================== ========== ===========
Option name Type Description Option name Type Description
=============== ========== =========== ================== ========== ===========
``execute_elf`` Boolean Allow running of binary :ref:`l0dables`. These files can be nefarious, so this option is off by default. ``execute_elf`` Boolean Allow running of binary :ref:`l0dables`. These files can be nefarious, so this option is off by default.
--------------- ---------- ----------- ------------------ ---------- -----------
``timezone`` String Timezone for card10; must be of format ``[+-]HHMM``. Examples: ``+0800``, ``-0200`` ``timezone`` String Timezone for card10; must be of format ``[+-]HHMM``. Examples: ``+0800``, ``-0200``
--------------- ---------- ----------- ------------------ ---------- -----------
``default_app`` String Full path to the exectutable file of the default application. If this option is not set,``apps/analog_clock/__init__.py`` is used. ``default_app`` String Full path to the exectutable file of the default application. If this option is not set,``apps/analog_clock/__init__.py`` is used.
=============== ========== =========== ------------------ ---------- -----------
``ble_log_enable`` Boolean Activate HCI level logging of BLE data. Creates a new btsnoop compatible log file named ``ble.log`` in the ``logs`` folder after each boot if BLE is activated. Keeps the last 10 files.
================== ========== ===========
#include "epicardium.h" #include "epicardium.h"
#include "modules/log.h" #include "modules/log.h"
#include "modules/config.h"
#include "fs/fs_util.h" #include "fs/fs_util.h"
#include "wsf_types.h" #include "wsf_types.h"
...@@ -12,6 +13,7 @@ ...@@ -12,6 +13,7 @@
#include "FreeRTOS.h" #include "FreeRTOS.h"
#include "timers.h" #include "timers.h"
#include <machine/endian.h>
#include <stdio.h> #include <stdio.h>
#include <string.h> #include <string.h>
#include <stdbool.h> #include <stdbool.h>
...@@ -20,6 +22,18 @@ ...@@ -20,6 +22,18 @@
#define WSF_BUF_POOLS 6 #define WSF_BUF_POOLS 6
#define WSF_BUF_SIZE (0x1048 * FACTOR) #define WSF_BUF_SIZE (0x1048 * FACTOR)
struct log_packet_header {
uint32_t original_length;
uint32_t included_length;
uint32_t packet_flags;
uint32_t cumulative_drops;
uint32_t timestamp_us_h;
uint32_t timestamp_us_l;
};
static const uint8_t log_header[] = {
'b', 't', 's', 'n', 'o', 'o', 'p', 0, 0, 0, 0, 1, 0, 0, 0x03, 0xea
};
uint32_t SystemHeapSize = WSF_BUF_SIZE; uint32_t SystemHeapSize = WSF_BUF_SIZE;
uint32_t SystemHeap[WSF_BUF_SIZE / 4]; uint32_t SystemHeap[WSF_BUF_SIZE / 4];
uint32_t SystemHeapStart; uint32_t SystemHeapStart;
...@@ -44,6 +58,11 @@ static StaticTimer_t x; ...@@ -44,6 +58,11 @@ static StaticTimer_t x;
static TimerHandle_t timerWakeup = NULL; static TimerHandle_t timerWakeup = NULL;
static int lasttick = 0; static int lasttick = 0;
static int log_fd;
static bool log_dirty = false;
static bool log_enabled = false;
static int log_lastflushtick = 0;
/*! \brief Stack initialization for app. */ /*! \brief Stack initialization for app. */
extern void StackInit(void); extern void StackInit(void);
extern void AppInit(void); extern void AppInit(void);
...@@ -70,6 +89,53 @@ static bool_t myTrace(const uint8_t *pBuf, uint32_t len) ...@@ -70,6 +89,53 @@ static bool_t myTrace(const uint8_t *pBuf, uint32_t len)
return FALSE; return FALSE;
} }
/*************************************************************************************************/
void WsfPDump(wsfPDumpType_t pdType, uint16_t length, uint8_t *pBuffer)
{
uint32_t direction;
uint8_t type;
if (log_enabled) {
switch (pdType) {
case WSF_PDUMP_TYPE_HCI_CMD:
direction = 0;
type = 0x01;
break;
case WSF_PDUMP_TYPE_HCI_EVT:
direction = 1;
type = 0x04;
break;
case WSF_PDUMP_TYPE_HCI_TX_ACL:
direction = 0;
type = 0x02;
break;
case WSF_PDUMP_TYPE_HCI_RX_ACL:
direction = 1;
type = 0x02;
break;
default:
break;
}
uint64_t tick = xTaskGetTickCount();
uint64_t timestamp_us = tick * 1000;
struct log_packet_header header = {
.original_length = __htonl(length + 1),
.included_length = __htonl(length + 1),
.packet_flags = __htonl(direction),
.cumulative_drops = __htonl(0),
.timestamp_us_h = __htonl(timestamp_us >> 32),
.timestamp_us_l = __htonl(timestamp_us & 0xFFFFFFFF)
};
epic_file_write(log_fd, &header, sizeof(header));
epic_file_write(log_fd, &type, sizeof(type));
epic_file_write(log_fd, pBuffer, length);
log_dirty = true;
}
}
/*************************************************************************************************/ /*************************************************************************************************/
static void WsfInit(void) static void WsfInit(void)
{ {
...@@ -239,6 +305,48 @@ static void scheduleTimer(void) ...@@ -239,6 +305,48 @@ static void scheduleTimer(void)
} }
} }
/*************************************************************************************************/ /*************************************************************************************************/
static void log_flush(void)
{
int tick = xTaskGetTickCount();
if (tick - log_lastflushtick > 5000) {
log_lastflushtick = tick;
if (log_dirty) {
log_dirty = false;
LOG_INFO("ble", "Flushing log");
epic_file_flush(log_fd);
}
}
}
/*************************************************************************************************/
static void log_rotate(void)
{
int i;
char filename_old[16];
char filename_new[16];
struct epic_stat stat;
if (epic_file_stat("logs/", &stat) != 0) {
epic_file_mkdir("logs");
}
if (epic_file_stat("logs/ble9.log", &stat) == 0) {
epic_file_unlink("logs/ble9.log");
}
for (i = 8; i > 0; i--) {
sprintf(filename_old, "logs/ble%d.log", i);
sprintf(filename_new, "logs/ble%d.log", i + 1);
if (epic_file_stat(filename_old, &stat) == 0) {
epic_file_rename(filename_old, filename_new);
}
}
if (epic_file_stat("logs/ble.log", &stat) == 0) {
epic_file_rename("logs/ble.log", "logs/ble1.log");
}
}
/*************************************************************************************************/
void vBleTask(void *pvParameters) void vBleTask(void *pvParameters)
{ {
ble_task_id = xTaskGetCurrentTaskHandle(); ble_task_id = xTaskGetCurrentTaskHandle();
...@@ -248,6 +356,15 @@ void vBleTask(void *pvParameters) ...@@ -248,6 +356,15 @@ void vBleTask(void *pvParameters)
*/ */
vTaskDelay(pdMS_TO_TICKS(500)); vTaskDelay(pdMS_TO_TICKS(500));
log_enabled = config_get_boolean_with_default("ble_log_enable", false);
if (log_enabled) {
LOG_INFO("ble", "Log is enabled");
log_rotate();
log_fd = epic_file_open("logs/ble.log", "w");
epic_file_write(log_fd, log_header, sizeof(log_header));
}
/* We are going to execute FreeRTOS functions from callbacks /* We are going to execute FreeRTOS functions from callbacks
* coming from this interrupt. Its priority needs to be * coming from this interrupt. Its priority needs to be
* reduced to allow this. */ * reduced to allow this. */
...@@ -286,5 +403,8 @@ void vBleTask(void *pvParameters) ...@@ -286,5 +403,8 @@ void vBleTask(void *pvParameters)
ulTaskNotifyTake(pdTRUE, portTICK_PERIOD_MS * 1000); ulTaskNotifyTake(pdTRUE, portTICK_PERIOD_MS * 1000);
wsfOsDispatcher(); wsfOsDispatcher();
scheduleTimer(); scheduleTimer();
if (log_enabled) {
log_flush();
}
} }
} }
...@@ -293,14 +293,10 @@ bool_t WsfTokenService(void); ...@@ -293,14 +293,10 @@ bool_t WsfTokenService(void);
/*! \brief 3 argument HCI error trace. */ /*! \brief 3 argument HCI error trace. */
#define HCI_TRACE_ERR3(msg, var1, var2, var3) WSF_TRACE3("HCI", "ERR", msg, var1, var2, var3) #define HCI_TRACE_ERR3(msg, var1, var2, var3) WSF_TRACE3("HCI", "ERR", msg, var1, var2, var3)
/*! \brief HCI PDUMP on command. */ #define HCI_PDUMP_CMD(len, pBuf) WsfPDump(WSF_PDUMP_TYPE_HCI_CMD, len, pBuf)
#define HCI_PDUMP_CMD(len, pBuf) #define HCI_PDUMP_EVT(len, pBuf) WsfPDump(WSF_PDUMP_TYPE_HCI_EVT, len, pBuf)
/*! \brief HCI PDUMP on event. */ #define HCI_PDUMP_TX_ACL(len, pBuf) WsfPDump(WSF_PDUMP_TYPE_HCI_TX_ACL, len, pBuf)
#define HCI_PDUMP_EVT(len, pBuf) #define HCI_PDUMP_RX_ACL(len, pBuf) WsfPDump(WSF_PDUMP_TYPE_HCI_RX_ACL, len, pBuf)
/*! \brief HCI PDUMP on transmitted ACL message. */
#define HCI_PDUMP_TX_ACL(len, pBuf)
/*! \brief HCI PDUMP on Received ACL message. */
#define HCI_PDUMP_RX_ACL(len, pBuf)
/*! \brief 0 argument DM info trace. */ /*! \brief 0 argument DM info trace. */
#define DM_TRACE_INFO0(msg) WSF_TRACE0("DM", "INFO", msg) #define DM_TRACE_INFO0(msg) WSF_TRACE0("DM", "INFO", msg)
...@@ -622,6 +618,25 @@ bool_t WsfTokenService(void); ...@@ -622,6 +618,25 @@ bool_t WsfTokenService(void);
#define LL_TRACE_ENABLE(ena) #define LL_TRACE_ENABLE(ena)
#endif #endif
/*! Protocol types */
typedef enum
{
WSF_PDUMP_TYPE_HCI_CMD = (1 << 0),
WSF_PDUMP_TYPE_HCI_EVT = (1 << 1),
WSF_PDUMP_TYPE_HCI_TX_ACL = (1 << 2),
WSF_PDUMP_TYPE_HCI_RX_ACL = (1 << 3),
WSF_PDUMP_TYPE_HCI_TX_ISO = (1 << 4),
WSF_PDUMP_TYPE_HCI_RX_ISO = (1 << 5),
WSF_PDUMP_TYPE_NONE = 0,
WSF_PDUMP_TYPE_ALL = 0xFFFF
} wsfPDumpType_t;
/**************************************************************************************************
Function Prototypes
**************************************************************************************************/
void WsfPDump(wsfPDumpType_t pdType, uint16_t length, uint8_t *pBuffer);
/*! \} */ /* WSF_TRACE_API */ /*! \} */ /* WSF_TRACE_API */
#ifdef __cplusplus #ifdef __cplusplus
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment