Merge 'Allow writing HCI layer log file'

See merge request !387

Documentation/card10-cfg.rst

@@ -34,12 +34,14 @@ Float     A single-precision (32-bit) floating-point number in base 10. Example:
 Supported options
 -----------------
 
-=============== ========== ===========
+================== ========== ===========
 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.
---------------- ---------- -----------
+------------------ ---------- -----------
 ``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.
-=============== ========== ===========
+------------------ ---------- -----------
+``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.
+================== ========== ===========

epicardium/ble/ble.c

 #include "epicardium.h"
 #include "modules/log.h"
+#include "modules/config.h"
 
 #include "fs/fs_util.h"
 #include "wsf_types.h"
@@ -12,6 +13,7 @@
 #include "FreeRTOS.h"
 #include "timers.h"
 
+#include <machine/endian.h>
 #include <stdio.h>
 #include <string.h>
 #include <stdbool.h>
@@ -20,6 +22,18 @@
 #define WSF_BUF_POOLS 6
 #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 SystemHeap[WSF_BUF_SIZE / 4];
 uint32_t SystemHeapStart;
@@ -44,6 +58,11 @@ static StaticTimer_t x;
 static TimerHandle_t timerWakeup = NULL;
 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. */
 extern void StackInit(void);
 extern void AppInit(void);
@@ -70,6 +89,73 @@ static bool_t myTrace(const uint8_t *pBuf, uint32_t len)
 
 	return FALSE;
 }
+
+/*************************************************************************************************/
+void WsfPDump(wsfPDumpType_t pdType, uint16_t length, uint8_t *pBuffer)
+{
+	uint32_t direction;
+	uint8_t type;
+	int ret;
+
+	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:
+			LOG_WARN("ble", "Unknown packet type to be logged");
+			return;
+		}
+
+		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)
+		};
+
+		ret = epic_file_write(log_fd, &header, sizeof(header));
+		if (ret != sizeof(header)) {
+			goto out_err;
+		}
+
+		ret = epic_file_write(log_fd, &type, sizeof(type));
+		if (ret != sizeof(type)) {
+			goto out_err;
+		}
+
+		ret = epic_file_write(log_fd, pBuffer, length);
+		if (ret != length) {
+			goto out_err;
+		}
+
+		log_dirty = true;
+	}
+
+	return;
+
+out_err:
+	LOG_WARN("ble", "Log file write failed. Logging diabled");
+	log_enabled = false;
+}
 /*************************************************************************************************/
 static void WsfInit(void)
 {
@@ -239,6 +325,95 @@ 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 int log_rotate(void)
+{
+	int i;
+	char filename_old[16];
+	char filename_new[16];
+	struct epic_stat stat;
+	int ret;
+
+	epic_file_stat("logs", &stat);
+
+	if (stat.type == EPICSTAT_FILE) {
+		return -1;
+	}
+
+	if (stat.type == EPICSTAT_NONE) {
+		ret = epic_file_mkdir("logs");
+		if (ret < 0) {
+			return ret;
+		}
+	}
+
+	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");
+	}
+
+	return 0;
+}
+/*************************************************************************************************/
+static void log_init(void)
+{
+	int ret;
+	log_enabled = config_get_boolean_with_default("ble_log_enable", false);
+
+	if (!log_enabled) {
+		return;
+	}
+
+	LOG_INFO("ble", "Log is enabled");
+
+	if (log_rotate() < 0) {
+		log_enabled = false;
+		LOG_WARN("ble", "Can not rotate logs. Logging disabled.");
+		return;
+	}
+
+	log_fd = epic_file_open("logs/ble.log", "w");
+	if (log_fd < 0) {
+		log_enabled = false;
+		LOG_WARN("ble", "Can not create log file. Logging disabled.");
+		return;
+	}
+
+	ret = epic_file_write(log_fd, log_header, sizeof(log_header));
+	if (ret != sizeof(log_header)) {
+		log_enabled = false;
+		LOG_WARN(
+			"ble",
+			"Can not create log file header. Logging disabled."
+		);
+		return;
+	}
+}
+/*************************************************************************************************/
 void vBleTask(void *pvParameters)
 {
 	ble_task_id = xTaskGetCurrentTaskHandle();
@@ -248,6 +423,8 @@ void vBleTask(void *pvParameters)
 	 */
 	vTaskDelay(pdMS_TO_TICKS(500));
 
+	log_init();
+
 	/* We are going to execute FreeRTOS functions from callbacks
 	 * coming from this interrupt. Its priority needs to be
 	 * reduced to allow this. */
@@ -286,5 +463,8 @@ void vBleTask(void *pvParameters)
 		ulTaskNotifyTake(pdTRUE, portTICK_PERIOD_MS * 1000);
 		wsfOsDispatcher();
 		scheduleTimer();
+		if (log_enabled) {
+			log_flush();
+		}
 	}
 }

lib/sdk/Libraries/BTLE/wsf/include/wsf_trace.h

@@ -293,14 +293,10 @@ bool_t WsfTokenService(void);
 /*! \brief 3 argument HCI error trace. */
 #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)
-/*! \brief HCI PDUMP on event. */
-#define HCI_PDUMP_EVT(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)
+#define HCI_PDUMP_CMD(len, pBuf)                    WsfPDump(WSF_PDUMP_TYPE_HCI_CMD, len, pBuf)
+#define HCI_PDUMP_EVT(len, pBuf)                    WsfPDump(WSF_PDUMP_TYPE_HCI_EVT, len, pBuf)
+#define HCI_PDUMP_TX_ACL(len, pBuf)                 WsfPDump(WSF_PDUMP_TYPE_HCI_TX_ACL, len, pBuf)
+#define HCI_PDUMP_RX_ACL(len, pBuf)                 WsfPDump(WSF_PDUMP_TYPE_HCI_RX_ACL, len, pBuf)
 
 /*! \brief 0 argument DM info trace. */
 #define DM_TRACE_INFO0(msg)                         WSF_TRACE0("DM", "INFO", msg)
@@ -622,6 +618,25 @@ bool_t WsfTokenService(void);
 #define LL_TRACE_ENABLE(ena)
 #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 */
 
 #ifdef __cplusplus