diff --git a/subsys/bluetooth/common/Kconfig b/subsys/bluetooth/common/Kconfig index efcd833acbc..746ce93be38 100644 --- a/subsys/bluetooth/common/Kconfig +++ b/subsys/bluetooth/common/Kconfig @@ -58,7 +58,6 @@ config BT_DEBUG_NONE config BT_DEBUG_LOG bool "Normal printf-style to console" select BT_DEBUG - select PRINTK select LOG help This option enables Bluetooth debug going to standard @@ -67,7 +66,7 @@ config BT_DEBUG_LOG config BT_DEBUG_MONITOR bool "Monitor protocol over UART" select BT_DEBUG - select PRINTK + select LOG select CONSOLE_HAS_DRIVER help Use a custom logging protocol over the console UART diff --git a/subsys/bluetooth/common/log.h b/subsys/bluetooth/common/log.h index e557f3aad99..dc91d71098d 100644 --- a/subsys/bluetooth/common/log.h +++ b/subsys/bluetooth/common/log.h @@ -26,31 +26,6 @@ extern "C" { #define BT_DBG_ENABLED 1 #endif -#if defined(CONFIG_BT_DEBUG_MONITOR) -#include - -/* These defines follow the values used by syslog(2) */ -#define BT_LOG_ERR 3 -#define BT_LOG_WARN 4 -#define BT_LOG_INFO 6 -#define BT_LOG_DBG 7 - -__printf_like(2, 3) void bt_log(int prio, const char *fmt, ...); - -#define BT_DBG(fmt, ...) \ - if (BT_DBG_ENABLED) { \ - bt_log(BT_LOG_DBG, "%s (%p): " fmt, \ - __func__, k_current_get(), ##__VA_ARGS__); \ - } - -#define BT_ERR(fmt, ...) bt_log(BT_LOG_ERR, "%s: " fmt, \ - __func__, ##__VA_ARGS__) -#define BT_WARN(fmt, ...) bt_log(BT_LOG_WARN, "%s: " fmt, \ - __func__, ##__VA_ARGS__) -#define BT_INFO(fmt, ...) bt_log(BT_LOG_INFO, fmt, ##__VA_ARGS__) - -#elif defined(CONFIG_BT_DEBUG_LOG) - #if BT_DBG_ENABLED #define LOG_LEVEL LOG_LEVEL_DBG #else @@ -73,20 +48,6 @@ LOG_MODULE_REGISTER(LOG_MODULE_NAME); #define BT_INFO(fmt, ...) LOG_INF(fmt, ##__VA_ARGS__) -#else - -static inline __printf_like(1, 2) void _bt_log_dummy(const char *fmt, ...) {}; - -#define BT_DBG(fmt, ...) \ - if (0) { \ - _bt_log_dummy(fmt, ##__VA_ARGS__); \ - } -#define BT_ERR BT_DBG -#define BT_WARN BT_DBG -#define BT_INFO BT_DBG - -#endif - #define BT_ASSERT(cond) if (!(cond)) { \ BT_ERR("assert: '" #cond "' failed"); \ k_oops(); \ diff --git a/subsys/bluetooth/host/monitor.c b/subsys/bluetooth/host/monitor.c index be523c4e024..19023d19b77 100644 --- a/subsys/bluetooth/host/monitor.c +++ b/subsys/bluetooth/host/monitor.c @@ -16,9 +16,13 @@ #include #include #include -#include #include +#include +#include +#include +#include + #include #include "monitor.h" @@ -29,6 +33,18 @@ */ #define MONITOR_INIT_PRIORITY 60 +/* These defines follow the values used by syslog(2) */ +#define BT_LOG_ERR 3 +#define BT_LOG_WARN 4 +#define BT_LOG_INFO 6 +#define BT_LOG_DBG 7 + +/* TS resolution is 1/10th of a millisecond */ +#define MONITOR_TS_FREQ 10000 + +/* Maximum (string) length of a log message */ +#define MONITOR_MSG_MAX 128 + static struct device *monitor_dev; enum { @@ -74,8 +90,14 @@ static void encode_drops(struct bt_monitor_hdr *hdr, u8_t type, } } -static inline void encode_hdr(struct bt_monitor_hdr *hdr, u16_t opcode, - u16_t len) +static u32_t monitor_ts_get(void) +{ + return (k_cycle_get_32() / + (sys_clock_hw_cycles_per_sec() / MONITOR_TS_FREQ)); +} + +static inline void encode_hdr(struct bt_monitor_hdr *hdr, u32_t timestamp, + u16_t opcode, u16_t len) { struct bt_monitor_ts32 *ts; @@ -84,7 +106,7 @@ static inline void encode_hdr(struct bt_monitor_hdr *hdr, u16_t opcode, ts = (void *)hdr->ext; ts->type = BT_MONITOR_TS32; - ts->ts32 = sys_cpu_to_le32(k_uptime_get() * 10); + ts->ts32 = timestamp; hdr->hdr_len = sizeof(*ts); encode_drops(hdr, BT_MONITOR_COMMAND_DROPS, &drops.cmd); @@ -100,12 +122,6 @@ static inline void encode_hdr(struct bt_monitor_hdr *hdr, u16_t opcode, hdr->data_len = sys_cpu_to_le16(4 + hdr->hdr_len + len); } -static int log_out(int c, void *unused) -{ - uart_poll_out(monitor_dev, c); - return 0; -} - static void drop_add(u16_t opcode) { switch (opcode) { @@ -135,47 +151,6 @@ static void drop_add(u16_t opcode) } } -void bt_log(int prio, const char *fmt, ...) -{ - struct bt_monitor_user_logging log; - struct bt_monitor_hdr hdr; - const char id[] = "bt"; - va_list ap; - int len; - - va_start(ap, fmt); - len = vsnprintk(NULL, 0, fmt, ap); - va_end(ap); - - if (len < 0) { - return; - } - - log.priority = prio; - log.ident_len = sizeof(id); - - if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) { - drop_add(BT_MONITOR_USER_LOGGING); - return; - } - - encode_hdr(&hdr, BT_MONITOR_USER_LOGGING, - sizeof(log) + sizeof(id) + len + 1); - - monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len); - monitor_send(&log, sizeof(log)); - monitor_send(id, sizeof(id)); - - va_start(ap, fmt); - _vprintk(log_out, NULL, fmt, ap); - va_end(ap); - - /* Terminate the string with null */ - uart_poll_out(monitor_dev, '\0'); - - atomic_clear_bit(&flags, BT_LOG_BUSY); -} - void bt_monitor_send(u16_t opcode, const void *data, size_t len) { struct bt_monitor_hdr hdr; @@ -185,7 +160,7 @@ void bt_monitor_send(u16_t opcode, const void *data, size_t len) return; } - encode_hdr(&hdr, opcode, len); + encode_hdr(&hdr, monitor_ts_get(), opcode, len); monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len); monitor_send(data, len); @@ -207,10 +182,10 @@ void bt_monitor_new_index(u8_t type, u8_t bus, bt_addr_t *addr, bt_monitor_send(BT_MONITOR_NEW_INDEX, &pkt, sizeof(pkt)); } -#if !defined(CONFIG_UART_CONSOLE) +#if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_LOG_PRINTK) static int monitor_console_out(int c) { - static char buf[128]; + static char buf[MONITOR_MSG_MAX]; static size_t len; if (atomic_test_and_set_bit(&flags, BT_CONSOLE_BUSY)) { @@ -241,6 +216,110 @@ extern void __stdout_hook_install(int (*fn)(int)); #define CONFIG_BT_MONITOR_ON_DEV_NAME CONFIG_UART_CONSOLE_ON_DEV_NAME #endif +struct monitor_log_ctx { + size_t total_len; + char msg[MONITOR_MSG_MAX]; +}; + +static int monitor_log_out(u8_t *data, size_t length, void *user_data) +{ + struct monitor_log_ctx *ctx = user_data; + size_t i; + + for (i = 0; i < length && ctx->total_len < sizeof(ctx->msg); i++) { + /* With CONFIG_LOG_PRINTK the line terminator will come as + * as part of messages. + */ + if (IS_ENABLED(CONFIG_LOG_PRINTK) && + (data[i] == '\r' || data[i] == '\n')) { + break; + } + + ctx->msg[ctx->total_len++] = data[i]; + } + + return length; +} + +static u8_t buf; + +LOG_OUTPUT_DEFINE(monitor_log_output, monitor_log_out, &buf, 1); + +static inline u8_t monitor_priority_get(u8_t log_level) +{ + static const u8_t prios[] = { + [LOG_LEVEL_NONE] = 0, + [LOG_LEVEL_ERR] = BT_LOG_ERR, + [LOG_LEVEL_WRN] = BT_LOG_WARN, + [LOG_LEVEL_INF] = BT_LOG_INFO, + [LOG_LEVEL_DBG] = BT_LOG_DBG, + }; + + if (log_level < ARRAY_SIZE(prios)) { + return prios[log_level]; + } + + return BT_LOG_DBG; +} + +static void monitor_log_put(const struct log_backend *const backend, + struct log_msg *msg) +{ + struct bt_monitor_user_logging log; + struct monitor_log_ctx ctx; + struct bt_monitor_hdr hdr; + const char id[] = "bt"; + + log_msg_get(msg); + + log_output_ctx_set(&monitor_log_output, &ctx); + + ctx.total_len = 0; + log_output_msg_process(&monitor_log_output, msg, + LOG_OUTPUT_FLAG_CRLF_NONE); + + if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) { + drop_add(BT_MONITOR_USER_LOGGING); + log_msg_put(msg); + return; + } + + encode_hdr(&hdr, msg->hdr.timestamp, BT_MONITOR_USER_LOGGING, + sizeof(log) + sizeof(id) + ctx.total_len + 1); + + log.priority = monitor_priority_get(msg->hdr.ids.level); + log.ident_len = sizeof(id); + + log_msg_put(msg); + + monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len); + monitor_send(&log, sizeof(log)); + monitor_send(id, sizeof(id)); + monitor_send(ctx.msg, ctx.total_len); + + /* Terminate the string with null */ + uart_poll_out(monitor_dev, '\0'); + + atomic_clear_bit(&flags, BT_LOG_BUSY); +} + +static void monitor_log_panic(const struct log_backend *const backend) +{ +} + +static void monitor_log_init(void) +{ + log_set_timestamp_func(monitor_ts_get, MONITOR_TS_FREQ); +} + +static const struct log_backend_api monitor_log_api = { + .put = monitor_log_put, + .panic = monitor_log_panic, + .init = monitor_log_init, +}; + +LOG_BACKEND_DEFINE(bt_monitor, monitor_log_api, true); + static int bt_monitor_init(struct device *d) { ARG_UNUSED(d); @@ -252,7 +331,7 @@ static int bt_monitor_init(struct device *d) uart_irq_tx_disable(monitor_dev); #endif -#if !defined(CONFIG_UART_CONSOLE) +#if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_LOG_PRINTK) __printk_hook_install(monitor_console_out); __stdout_hook_install(monitor_console_out); #endif