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