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 cnt = SEGGER_RTT_WriteNoLock(CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER,
131 rtt_buf, rtt_buf_offset);
132 } else {
133 cnt = SEGGER_RTT_Write(CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER,
134 rtt_buf, rtt_buf_offset);
135 }
136 }
137
138 if (!cnt) {
139 drop_add(hdr->opcode);
140 }
141
142 /* Prepare for the next packet */
143 rtt_buf_offset = 0;
144 }
145
poll_out(char c)146 static void poll_out(char c)
147 {
148 monitor_send(&c, sizeof(c));
149 }
150 #elif defined(CONFIG_BT_DEBUG_MONITOR_UART)
151 static const struct device *const monitor_dev =
152 #if DT_HAS_CHOSEN(zephyr_bt_mon_uart)
153 DEVICE_DT_GET(DT_CHOSEN(zephyr_bt_mon_uart));
154 #elif !defined(CONFIG_UART_CONSOLE) && DT_HAS_CHOSEN(zephyr_console)
155 /* Fall back to console UART if it's available */
156 DEVICE_DT_GET(DT_CHOSEN(zephyr_console));
157 #else
158 NULL;
159 #error "BT_DEBUG_MONITOR_UART enabled but no UART specified"
160 #endif
161
poll_out(char c)162 static void poll_out(char c)
163 {
164 uart_poll_out(monitor_dev, c);
165 }
166
monitor_send(const void * data,size_t len)167 static void monitor_send(const void *data, size_t len)
168 {
169 const uint8_t *buf = data;
170
171 while (len--) {
172 poll_out(*buf++);
173 }
174 }
175 #endif /* CONFIG_BT_DEBUG_MONITOR_UART */
176
encode_drops(struct bt_monitor_hdr * hdr,uint8_t type,atomic_t * val)177 static void encode_drops(struct bt_monitor_hdr *hdr, uint8_t type,
178 atomic_t *val)
179 {
180 atomic_val_t count;
181
182 count = atomic_set(val, 0);
183 if (count) {
184 hdr->ext[hdr->hdr_len++] = type;
185 hdr->ext[hdr->hdr_len++] = MIN(count, 255);
186 }
187 }
188
monitor_ts_get(void)189 static uint32_t monitor_ts_get(void)
190 {
191 uint64_t cycle;
192
193 if (IS_ENABLED(CONFIG_TIMER_HAS_64BIT_CYCLE_COUNTER)) {
194 cycle = k_cycle_get_64();
195 } else {
196 cycle = k_cycle_get_32();
197 }
198
199 return (cycle / (sys_clock_hw_cycles_per_sec() / MONITOR_TS_FREQ));
200 }
201
encode_hdr(struct bt_monitor_hdr * hdr,uint32_t timestamp,uint16_t opcode,uint16_t len)202 static inline void encode_hdr(struct bt_monitor_hdr *hdr, uint32_t timestamp,
203 uint16_t opcode, uint16_t len)
204 {
205 struct bt_monitor_ts32 *ts;
206
207 hdr->opcode = sys_cpu_to_le16(opcode);
208 hdr->flags = 0U;
209
210 ts = (void *)hdr->ext;
211 ts->type = BT_MONITOR_TS32;
212 ts->ts32 = timestamp;
213 hdr->hdr_len = sizeof(*ts);
214
215 encode_drops(hdr, BT_MONITOR_COMMAND_DROPS, &drops.cmd);
216 encode_drops(hdr, BT_MONITOR_EVENT_DROPS, &drops.evt);
217 encode_drops(hdr, BT_MONITOR_ACL_TX_DROPS, &drops.acl_tx);
218 encode_drops(hdr, BT_MONITOR_ACL_RX_DROPS, &drops.acl_rx);
219 #if defined(CONFIG_BT_CLASSIC)
220 encode_drops(hdr, BT_MONITOR_SCO_TX_DROPS, &drops.sco_tx);
221 encode_drops(hdr, BT_MONITOR_SCO_RX_DROPS, &drops.sco_rx);
222 #endif
223 encode_drops(hdr, BT_MONITOR_OTHER_DROPS, &drops.other);
224
225 hdr->data_len = sys_cpu_to_le16(4 + hdr->hdr_len + len);
226 }
227
bt_monitor_send(uint16_t opcode,const void * data,size_t len)228 void bt_monitor_send(uint16_t opcode, const void *data, size_t len)
229 {
230 struct bt_monitor_hdr hdr;
231
232 if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) {
233 drop_add(opcode);
234 return;
235 }
236
237 encode_hdr(&hdr, monitor_ts_get(), opcode, len);
238
239 monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len);
240 monitor_send(data, len);
241
242 atomic_clear_bit(&flags, BT_LOG_BUSY);
243 }
244
bt_monitor_new_index(uint8_t type,uint8_t bus,const bt_addr_t * addr,const char * name)245 void bt_monitor_new_index(uint8_t type, uint8_t bus, const bt_addr_t *addr,
246 const char *name)
247 {
248 struct bt_monitor_new_index pkt;
249
250 pkt.type = type;
251 pkt.bus = bus;
252 memcpy(pkt.bdaddr, addr, 6);
253 strncpy(pkt.name, name, sizeof(pkt.name) - 1);
254 pkt.name[sizeof(pkt.name) - 1] = '\0';
255
256 bt_monitor_send(BT_MONITOR_NEW_INDEX, &pkt, sizeof(pkt));
257 }
258
259 #if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_RTT_CONSOLE) && !defined(CONFIG_LOG_PRINTK)
monitor_console_out(int c)260 static int monitor_console_out(int c)
261 {
262 static char buf[MONITOR_MSG_MAX];
263 static size_t len;
264
265 if (atomic_test_and_set_bit(&flags, BT_CONSOLE_BUSY)) {
266 return c;
267 }
268
269 if (c != '\n' && len < sizeof(buf) - 1) {
270 buf[len++] = c;
271 atomic_clear_bit(&flags, BT_CONSOLE_BUSY);
272 return c;
273 }
274
275 buf[len++] = '\0';
276
277 bt_monitor_send(BT_MONITOR_SYSTEM_NOTE, buf, len);
278 len = 0;
279
280 atomic_clear_bit(&flags, BT_CONSOLE_BUSY);
281
282 return c;
283 }
284 #endif /* !CONFIG_UART_CONSOLE && !CONFIG_RTT_CONSOLE && !CONFIG_LOG_PRINTK */
285
286 #ifndef CONFIG_LOG_MODE_MINIMAL
287 struct monitor_log_ctx {
288 size_t total_len;
289 char msg[MONITOR_MSG_MAX];
290 };
291
monitor_log_out(uint8_t * data,size_t length,void * user_data)292 static int monitor_log_out(uint8_t *data, size_t length, void *user_data)
293 {
294 struct monitor_log_ctx *ctx = user_data;
295 size_t i;
296
297 for (i = 0; i < length && ctx->total_len < sizeof(ctx->msg); i++) {
298 /* With CONFIG_LOG_PRINTK the line terminator will come as
299 * as part of messages.
300 */
301 if (IS_ENABLED(CONFIG_LOG_PRINTK) &&
302 (data[i] == '\r' || data[i] == '\n')) {
303 break;
304 }
305
306 ctx->msg[ctx->total_len++] = data[i];
307 }
308
309 return length;
310 }
311
312 static uint8_t buf;
313
314 LOG_OUTPUT_DEFINE(monitor_log_output, monitor_log_out, &buf, 1);
315
monitor_priority_get(uint8_t log_level)316 static inline uint8_t monitor_priority_get(uint8_t log_level)
317 {
318 static const uint8_t prios[] = {
319 [LOG_LEVEL_NONE] = 0,
320 [LOG_LEVEL_ERR] = BT_LOG_ERR,
321 [LOG_LEVEL_WRN] = BT_LOG_WARN,
322 [LOG_LEVEL_INF] = BT_LOG_INFO,
323 [LOG_LEVEL_DBG] = BT_LOG_DBG,
324 };
325
326 if (log_level < ARRAY_SIZE(prios)) {
327 return prios[log_level];
328 }
329
330 return BT_LOG_DBG;
331 }
332
monitor_log_process(const struct log_backend * const backend,union log_msg_generic * msg)333 static void monitor_log_process(const struct log_backend *const backend,
334 union log_msg_generic *msg)
335 {
336 struct bt_monitor_user_logging user_log;
337 struct monitor_log_ctx ctx;
338 struct bt_monitor_hdr hdr;
339 static const char id[] = "bt";
340
341 log_output_ctx_set(&monitor_log_output, &ctx);
342
343 ctx.total_len = 0;
344 log_output_msg_process(&monitor_log_output, &msg->log,
345 LOG_OUTPUT_FLAG_CRLF_NONE);
346
347 if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) {
348 drop_add(BT_MONITOR_USER_LOGGING);
349 return;
350 }
351
352 encode_hdr(&hdr, (uint32_t)log_msg_get_timestamp(&msg->log),
353 BT_MONITOR_USER_LOGGING,
354 sizeof(user_log) + sizeof(id) + ctx.total_len + 1);
355
356 user_log.priority = monitor_priority_get(log_msg_get_level(&msg->log));
357 user_log.ident_len = sizeof(id);
358
359 monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len);
360 monitor_send(&user_log, sizeof(user_log));
361 monitor_send(id, sizeof(id));
362 monitor_send(ctx.msg, ctx.total_len);
363
364 /* Terminate the string with null */
365 poll_out('\0');
366
367 atomic_clear_bit(&flags, BT_LOG_BUSY);
368 }
369
monitor_log_panic(const struct log_backend * const backend)370 static void monitor_log_panic(const struct log_backend *const backend)
371 {
372 #if defined(CONFIG_BT_DEBUG_MONITOR_RTT)
373 panic_mode = true;
374 #endif
375 }
376
monitor_log_init(const struct log_backend * const backend)377 static void monitor_log_init(const struct log_backend *const backend)
378 {
379 log_set_timestamp_func(monitor_ts_get, MONITOR_TS_FREQ);
380 }
381
382 static const struct log_backend_api monitor_log_api = {
383 .process = monitor_log_process,
384 .panic = monitor_log_panic,
385 .init = monitor_log_init,
386 };
387
388 LOG_BACKEND_DEFINE(bt_monitor, monitor_log_api, true);
389 #endif /* CONFIG_LOG_MODE_MINIMAL */
390
bt_monitor_init(void)391 static int bt_monitor_init(void)
392 {
393
394 #if defined(CONFIG_BT_DEBUG_MONITOR_RTT)
395 static uint8_t rtt_up_buf[RTT_BUF_SIZE];
396
397 SEGGER_RTT_ConfigUpBuffer(CONFIG_BT_DEBUG_MONITOR_RTT_BUFFER,
398 RTT_BUFFER_NAME, rtt_up_buf, RTT_BUF_SIZE,
399 SEGGER_RTT_MODE_NO_BLOCK_SKIP);
400 #elif defined(CONFIG_BT_DEBUG_MONITOR_UART)
401 __ASSERT_NO_MSG(device_is_ready(monitor_dev));
402
403 #if defined(CONFIG_UART_INTERRUPT_DRIVEN)
404 uart_irq_rx_disable(monitor_dev);
405 uart_irq_tx_disable(monitor_dev);
406 #endif /* CONFIG_UART_INTERRUPT_DRIVEN */
407 #endif /* CONFIG_BT_DEBUG_MONITOR_UART */
408
409 #if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_RTT_CONSOLE) && !defined(CONFIG_LOG_PRINTK)
410 __printk_hook_install(monitor_console_out);
411 __stdout_hook_install(monitor_console_out);
412 #endif /* !CONFIG_UART_CONSOLE && !CONFIG_RTT_CONSOLE && !CONFIG_LOG_PRINTK */
413
414 return 0;
415 }
416
417 SYS_INIT(bt_monitor_init, PRE_KERNEL_1, MONITOR_INIT_PRIORITY);
418
