1 /** @file
2 * @brief Custom logging over UART
3 */
4
5 /*
6 * Copyright (c) 2016 Intel Corporation
7 *
8 * SPDX-License-Identifier: Apache-2.0
9 */
10
11 #include <stdbool.h>
12 #include <stddef.h>
13 #include <stdint.h>
14 #include <string.h>
15
16 #include <zephyr/bluetooth/addr.h>
17 #include <zephyr/bluetooth/buf.h>
18 #include <zephyr/device.h>
19 #include <zephyr/drivers/uart_pipe.h>
20 #include <zephyr/init.h>
21 #include <zephyr/kernel.h>
22 #include <zephyr/logging/log_backend.h>
23 #include <zephyr/logging/log_core.h>
24 #include <zephyr/logging/log_msg.h>
25 #include <zephyr/logging/log_output.h>
26 #include <zephyr/logging/log_ctrl.h>
27 #include <zephyr/logging/log.h>
28 #include <zephyr/sys/atomic.h>
29 #include <zephyr/sys/atomic_types.h>
30 #include <zephyr/sys/byteorder.h>
31 #include <zephyr/sys/printk-hooks.h>
32 #include <zephyr/sys/libc-hooks.h>
33 #include <zephyr/drivers/uart.h>
34 #include <zephyr/sys/time_units.h>
35 #include <zephyr/sys/util.h>
36 #include <zephyr/sys/util_macro.h>
37
38 #include "monitor.h"
39
40 /* This is the same default priority as for other console handlers,
41 * except that we're not exporting it as a Kconfig variable until a
42 * clear need arises.
43 */
44 #define MONITOR_INIT_PRIORITY 60
45
46 /* These defines follow the values used by syslog(2) */
47 #define BT_LOG_ERR 3
48 #define BT_LOG_WARN 4
49 #define BT_LOG_INFO 6
50 #define BT_LOG_DBG 7
51
52 /* TS resolution is 1/10th of a millisecond */
53 #define MONITOR_TS_FREQ 10000
54
55 /* Maximum (string) length of a log message */
56 #define MONITOR_MSG_MAX 128
57
58 enum {
59 BT_LOG_BUSY,
60 BT_CONSOLE_BUSY,
61 };
62
63 static atomic_t flags;
64
65 static struct {
66 atomic_t cmd;
67 atomic_t evt;
68 atomic_t acl_tx;
69 atomic_t acl_rx;
70 #if defined(CONFIG_BT_CLASSIC)
71 atomic_t sco_tx;
72 atomic_t sco_rx;
73 #endif
74 atomic_t other;
75 } drops;
76
drop_add(uint16_t opcode)77 static void drop_add(uint16_t opcode)
78 {
79 switch (opcode) {
80 case BT_MONITOR_COMMAND_PKT:
81 atomic_inc(&drops.cmd);
82 break;
83 case BT_MONITOR_EVENT_PKT:
84 atomic_inc(&drops.evt);
85 break;
86 case BT_MONITOR_ACL_TX_PKT:
87 atomic_inc(&drops.acl_tx);
88 break;
89 case BT_MONITOR_ACL_RX_PKT:
90 atomic_inc(&drops.acl_rx);
91 break;
92 #if defined(CONFIG_BT_CLASSIC)
93 case BT_MONITOR_SCO_TX_PKT:
94 atomic_inc(&drops.sco_tx);
95 break;
96 case BT_MONITOR_SCO_RX_PKT:
97 atomic_inc(&drops.sco_rx);
98 break;
99 #endif
100 default:
101 atomic_inc(&drops.other);
102 break;
103 }
104 }
105
106 #if defined(CONFIG_BT_DEBUG_MONITOR_RTT)
107 #include <SEGGER_RTT.h>
108
109 static bool panic_mode;
110
111 #define RTT_BUFFER_NAME CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER_NAME
112 #define RTT_BUF_SIZE CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER_SIZE
113
monitor_send(const void * data,size_t len)114 static void monitor_send(const void *data, size_t len)
115 {
116 static uint8_t rtt_buf[RTT_BUF_SIZE];
117 static size_t rtt_buf_offset;
118 struct bt_monitor_hdr *hdr;
119 unsigned int cnt = 0;
120 bool drop;
121
122 /* Drop any packet which cannot fit the buffer */
123 drop = rtt_buf_offset + len > sizeof(rtt_buf);
124 if (!drop) {
125 (void)memcpy(rtt_buf + rtt_buf_offset, data, len);
126 }
127
128 rtt_buf_offset += len;
129
130 /* Check if the packet is complete */
131 hdr = (struct bt_monitor_hdr *)rtt_buf;
132 if (rtt_buf_offset < sizeof(hdr->data_len) + hdr->data_len) {
133 return;
134 }
135
136 if (!drop) {
137 if (panic_mode) {
138 cnt = SEGGER_RTT_WriteNoLock(CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER,
139 rtt_buf, rtt_buf_offset);
140 } else {
141 cnt = SEGGER_RTT_Write(CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER,
142 rtt_buf, rtt_buf_offset);
143 }
144 }
145
146 if (!cnt) {
147 drop_add(hdr->opcode);
148 }
149
150 /* Prepare for the next packet */
151 rtt_buf_offset = 0;
152 }
153
poll_out(char c)154 static void poll_out(char c)
155 {
156 monitor_send(&c, sizeof(c));
157 }
158 #elif defined(CONFIG_BT_DEBUG_MONITOR_UART)
159 static const struct device *const monitor_dev =
160 #if DT_HAS_CHOSEN(zephyr_bt_mon_uart)
161 DEVICE_DT_GET(DT_CHOSEN(zephyr_bt_mon_uart));
162 #elif !defined(CONFIG_UART_CONSOLE) && DT_HAS_CHOSEN(zephyr_console)
163 /* Fall back to console UART if it's available */
164 DEVICE_DT_GET(DT_CHOSEN(zephyr_console));
165 #else
166 NULL;
167 #error "BT_DEBUG_MONITOR_UART enabled but no UART specified"
168 #endif
169
poll_out(char c)170 static void poll_out(char c)
171 {
172 uart_poll_out(monitor_dev, c);
173 }
174
monitor_send(const void * data,size_t len)175 static void monitor_send(const void *data, size_t len)
176 {
177 const uint8_t *buf = data;
178
179 while (len--) {
180 poll_out(*buf++);
181 }
182 }
183 #endif /* CONFIG_BT_DEBUG_MONITOR_UART */
184
encode_drops(struct bt_monitor_hdr * hdr,uint8_t type,atomic_t * val)185 static void encode_drops(struct bt_monitor_hdr *hdr, uint8_t type,
186 atomic_t *val)
187 {
188 atomic_val_t count;
189
190 count = atomic_set(val, 0);
191 if (count) {
192 hdr->ext[hdr->hdr_len++] = type;
193 hdr->ext[hdr->hdr_len++] = MIN(count, 255);
194 }
195 }
196
monitor_ts_get(void)197 static uint32_t monitor_ts_get(void)
198 {
199 uint64_t cycle;
200
201 if (IS_ENABLED(CONFIG_TIMER_HAS_64BIT_CYCLE_COUNTER)) {
202 cycle = k_cycle_get_64();
203 } else {
204 cycle = k_cycle_get_32();
205 }
206
207 return (cycle / (sys_clock_hw_cycles_per_sec() / MONITOR_TS_FREQ));
208 }
209
encode_hdr(struct bt_monitor_hdr * hdr,uint32_t timestamp,uint16_t opcode,uint16_t len)210 static inline void encode_hdr(struct bt_monitor_hdr *hdr, uint32_t timestamp,
211 uint16_t opcode, uint16_t len)
212 {
213 struct bt_monitor_ts32 *ts;
214
215 hdr->opcode = sys_cpu_to_le16(opcode);
216 hdr->flags = 0U;
217
218 ts = (void *)hdr->ext;
219 ts->type = BT_MONITOR_TS32;
220 ts->ts32 = timestamp;
221 hdr->hdr_len = sizeof(*ts);
222
223 encode_drops(hdr, BT_MONITOR_COMMAND_DROPS, &drops.cmd);
224 encode_drops(hdr, BT_MONITOR_EVENT_DROPS, &drops.evt);
225 encode_drops(hdr, BT_MONITOR_ACL_TX_DROPS, &drops.acl_tx);
226 encode_drops(hdr, BT_MONITOR_ACL_RX_DROPS, &drops.acl_rx);
227 #if defined(CONFIG_BT_CLASSIC)
228 encode_drops(hdr, BT_MONITOR_SCO_TX_DROPS, &drops.sco_tx);
229 encode_drops(hdr, BT_MONITOR_SCO_RX_DROPS, &drops.sco_rx);
230 #endif
231 encode_drops(hdr, BT_MONITOR_OTHER_DROPS, &drops.other);
232
233 hdr->data_len = sys_cpu_to_le16(4 + hdr->hdr_len + len);
234 }
235
bt_monitor_send(uint16_t opcode,const void * data,size_t len)236 void bt_monitor_send(uint16_t opcode, const void *data, size_t len)
237 {
238 struct bt_monitor_hdr hdr;
239
240 if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) {
241 drop_add(opcode);
242 return;
243 }
244
245 encode_hdr(&hdr, monitor_ts_get(), opcode, len);
246
247 monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len);
248 monitor_send(data, len);
249
250 atomic_clear_bit(&flags, BT_LOG_BUSY);
251 }
252
bt_monitor_new_index(uint8_t type,uint8_t bus,const bt_addr_t * addr,const char * name)253 void bt_monitor_new_index(uint8_t type, uint8_t bus, const bt_addr_t *addr,
254 const char *name)
255 {
256 struct bt_monitor_new_index pkt;
257
258 pkt.type = type;
259 pkt.bus = bus;
260 memcpy(pkt.bdaddr, addr, 6);
261 strncpy(pkt.name, name, sizeof(pkt.name) - 1);
262 pkt.name[sizeof(pkt.name) - 1] = '\0';
263
264 bt_monitor_send(BT_MONITOR_NEW_INDEX, &pkt, sizeof(pkt));
265 }
266
267 #if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_RTT_CONSOLE) && !defined(CONFIG_LOG_PRINTK)
monitor_console_out(int c)268 static int monitor_console_out(int c)
269 {
270 static char buf[MONITOR_MSG_MAX];
271 static size_t len;
272
273 if (atomic_test_and_set_bit(&flags, BT_CONSOLE_BUSY)) {
274 return c;
275 }
276
277 if (c != '\n' && len < sizeof(buf) - 1) {
278 buf[len++] = c;
279 atomic_clear_bit(&flags, BT_CONSOLE_BUSY);
280 return c;
281 }
282
283 buf[len++] = '\0';
284
285 bt_monitor_send(BT_MONITOR_SYSTEM_NOTE, buf, len);
286 len = 0;
287
288 atomic_clear_bit(&flags, BT_CONSOLE_BUSY);
289
290 return c;
291 }
292 #endif /* !CONFIG_UART_CONSOLE && !CONFIG_RTT_CONSOLE && !CONFIG_LOG_PRINTK */
293
294 #ifndef CONFIG_LOG_MODE_MINIMAL
295 struct monitor_log_ctx {
296 size_t total_len;
297 char msg[MONITOR_MSG_MAX];
298 };
299
monitor_log_out(uint8_t * data,size_t length,void * user_data)300 static int monitor_log_out(uint8_t *data, size_t length, void *user_data)
301 {
302 struct monitor_log_ctx *ctx = user_data;
303 size_t i;
304
305 for (i = 0; i < length && ctx->total_len < sizeof(ctx->msg); i++) {
306 /* With CONFIG_LOG_PRINTK the line terminator will come as
307 * as part of messages.
308 */
309 if (IS_ENABLED(CONFIG_LOG_PRINTK) &&
310 (data[i] == '\r' || data[i] == '\n')) {
311 break;
312 }
313
314 ctx->msg[ctx->total_len++] = data[i];
315 }
316
317 return length;
318 }
319
320 static uint8_t buf;
321
322 LOG_OUTPUT_DEFINE(monitor_log_output, monitor_log_out, &buf, 1);
323
monitor_priority_get(uint8_t log_level)324 static inline uint8_t monitor_priority_get(uint8_t log_level)
325 {
326 static const uint8_t prios[] = {
327 [LOG_LEVEL_NONE] = 0,
328 [LOG_LEVEL_ERR] = BT_LOG_ERR,
329 [LOG_LEVEL_WRN] = BT_LOG_WARN,
330 [LOG_LEVEL_INF] = BT_LOG_INFO,
331 [LOG_LEVEL_DBG] = BT_LOG_DBG,
332 };
333
334 if (log_level < ARRAY_SIZE(prios)) {
335 return prios[log_level];
336 }
337
338 return BT_LOG_DBG;
339 }
340
monitor_log_process(const struct log_backend * const backend,union log_msg_generic * msg)341 static void monitor_log_process(const struct log_backend *const backend,
342 union log_msg_generic *msg)
343 {
344 struct bt_monitor_user_logging user_log;
345 struct monitor_log_ctx ctx;
346 struct bt_monitor_hdr hdr;
347 static const char id[] = "bt";
348
349 log_output_ctx_set(&monitor_log_output, &ctx);
350
351 ctx.total_len = 0;
352 log_output_msg_process(&monitor_log_output, &msg->log,
353 LOG_OUTPUT_FLAG_CRLF_NONE);
354
355 if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) {
356 drop_add(BT_MONITOR_USER_LOGGING);
357 return;
358 }
359
360 encode_hdr(&hdr, (uint32_t)log_msg_get_timestamp(&msg->log),
361 BT_MONITOR_USER_LOGGING,
362 sizeof(user_log) + sizeof(id) + ctx.total_len + 1);
363
364 user_log.priority = monitor_priority_get(log_msg_get_level(&msg->log));
365 user_log.ident_len = sizeof(id);
366
367 monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len);
368 monitor_send(&user_log, sizeof(user_log));
369 monitor_send(id, sizeof(id));
370 monitor_send(ctx.msg, ctx.total_len);
371
372 /* Terminate the string with null */
373 poll_out('\0');
374
375 atomic_clear_bit(&flags, BT_LOG_BUSY);
376 }
377
monitor_log_panic(const struct log_backend * const backend)378 static void monitor_log_panic(const struct log_backend *const backend)
379 {
380 #if defined(CONFIG_BT_DEBUG_MONITOR_RTT)
381 panic_mode = true;
382 #endif
383 }
384
monitor_log_init(const struct log_backend * const backend)385 static void monitor_log_init(const struct log_backend *const backend)
386 {
387 log_set_timestamp_func(monitor_ts_get, MONITOR_TS_FREQ);
388 }
389
390 static const struct log_backend_api monitor_log_api = {
391 .process = monitor_log_process,
392 .panic = monitor_log_panic,
393 .init = monitor_log_init,
394 };
395
396 LOG_BACKEND_DEFINE(bt_monitor, monitor_log_api, true);
397 #endif /* CONFIG_LOG_MODE_MINIMAL */
398
bt_monitor_init(void)399 static int bt_monitor_init(void)
400 {
401
402 #if defined(CONFIG_BT_DEBUG_MONITOR_RTT)
403 static uint8_t rtt_up_buf[RTT_BUF_SIZE];
404
405 SEGGER_RTT_ConfigUpBuffer(CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER,
406 RTT_BUFFER_NAME, rtt_up_buf, RTT_BUF_SIZE,
407 SEGGER_RTT_MODE_NO_BLOCK_SKIP);
408 #elif defined(CONFIG_BT_DEBUG_MONITOR_UART)
409 __ASSERT_NO_MSG(device_is_ready(monitor_dev));
410
411 #if defined(CONFIG_UART_INTERRUPT_DRIVEN)
412 uart_irq_rx_disable(monitor_dev);
413 uart_irq_tx_disable(monitor_dev);
414 #endif /* CONFIG_UART_INTERRUPT_DRIVEN */
415 #endif /* CONFIG_BT_DEBUG_MONITOR_UART */
416
417 #if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_RTT_CONSOLE) && !defined(CONFIG_LOG_PRINTK)
418 __printk_hook_install(monitor_console_out);
419 __stdout_hook_install(monitor_console_out);
420 #endif /* !CONFIG_UART_CONSOLE && !CONFIG_RTT_CONSOLE && !CONFIG_LOG_PRINTK */
421
422 return 0;
423 }
424
425 SYS_INIT(bt_monitor_init, PRE_KERNEL_1, MONITOR_INIT_PRIORITY);
426