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 <ble_types/types.h>
12 #include <stdbool.h>
13
14 #if defined(CONFIG_BT_DEBUG_MONITOR)
15 #include <ble_os.h>
16 #include <bt_device.h>
17 #include <init.h>
18 #include <drivers/console/uart_pipe.h>
19 #include <misc/byteorder.h>
20 #include <misc/printk.h>
21 #include <uart.h>
22
23 #include <logging/log_backend.h>
24 #include <logging/log_output.h>
25 #include <logging/log_ctrl.h>
26 #include <logging/log.h>
27
28 #include <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 static struct device *monitor_dev;
51
52 enum {
53 BT_LOG_BUSY,
54 BT_CONSOLE_BUSY,
55 };
56
57 static atomic_t flags;
58
59 static struct {
60 atomic_t cmd;
61 atomic_t evt;
62 atomic_t acl_tx;
63 atomic_t acl_rx;
64 #if defined(CONFIG_BT_BREDR)
65 atomic_t sco_tx;
66 atomic_t sco_rx;
67 #endif
68 atomic_t other;
69 } drops;
70
71 extern int z_prf(int (*func)(), void *dest,
72 const char *format, va_list vargs);
73
monitor_send(const void * data,size_t len)74 static void monitor_send(const void *data, size_t len)
75 {
76 const u8_t *buf = data;
77
78 while (len--) {
79 uart_poll_out(monitor_dev, *buf++);
80 }
81 }
82
encode_drops(struct bt_monitor_hdr * hdr,u8_t type,atomic_t * val)83 static void encode_drops(struct bt_monitor_hdr *hdr, u8_t type,
84 atomic_t *val)
85 {
86 atomic_val_t count;
87
88 count = atomic_set(val, 0);
89 if (count) {
90 hdr->ext[hdr->hdr_len++] = type;
91 hdr->ext[hdr->hdr_len++] = MIN(count, 255);
92 }
93 }
94
monitor_ts_get(void)95 static bt_u32_t monitor_ts_get(void)
96 {
97 return (k_cycle_get_32() /
98 (sys_clock_hw_cycles_per_sec() / MONITOR_TS_FREQ));
99 }
100
encode_hdr(struct bt_monitor_hdr * hdr,bt_u32_t timestamp,u16_t opcode,u16_t len)101 static inline void encode_hdr(struct bt_monitor_hdr *hdr, bt_u32_t timestamp,
102 u16_t opcode, u16_t len)
103 {
104 struct bt_monitor_ts32 *ts;
105
106 hdr->opcode = sys_cpu_to_le16(opcode);
107 hdr->flags = 0U;
108
109 ts = (void *)hdr->ext;
110 ts->type = BT_MONITOR_TS32;
111 ts->ts32 = timestamp;
112 hdr->hdr_len = sizeof(*ts);
113
114 encode_drops(hdr, BT_MONITOR_COMMAND_DROPS, &drops.cmd);
115 encode_drops(hdr, BT_MONITOR_EVENT_DROPS, &drops.evt);
116 encode_drops(hdr, BT_MONITOR_ACL_TX_DROPS, &drops.acl_tx);
117 encode_drops(hdr, BT_MONITOR_ACL_RX_DROPS, &drops.acl_rx);
118 #if defined(CONFIG_BT_BREDR)
119 encode_drops(hdr, BT_MONITOR_SCO_TX_DROPS, &drops.sco_tx);
120 encode_drops(hdr, BT_MONITOR_SCO_RX_DROPS, &drops.sco_rx);
121 #endif
122 encode_drops(hdr, BT_MONITOR_OTHER_DROPS, &drops.other);
123
124 hdr->data_len = sys_cpu_to_le16(4 + hdr->hdr_len + len);
125 }
126
drop_add(u16_t opcode)127 static void drop_add(u16_t opcode)
128 {
129 switch (opcode) {
130 case BT_MONITOR_COMMAND_PKT:
131 atomic_inc(&drops.cmd);
132 break;
133 case BT_MONITOR_EVENT_PKT:
134 atomic_inc(&drops.evt);
135 break;
136 case BT_MONITOR_ACL_TX_PKT:
137 atomic_inc(&drops.acl_tx);
138 break;
139 case BT_MONITOR_ACL_RX_PKT:
140 atomic_inc(&drops.acl_rx);
141 break;
142 #if defined(CONFIG_BT_BREDR)
143 case BT_MONITOR_SCO_TX_PKT:
144 atomic_inc(&drops.sco_tx);
145 break;
146 case BT_MONITOR_SCO_RX_PKT:
147 atomic_inc(&drops.sco_rx);
148 break;
149 #endif
150 default:
151 atomic_inc(&drops.other);
152 break;
153 }
154 }
155
bt_monitor_send(u16_t opcode,const void * data,size_t len)156 void bt_monitor_send(u16_t opcode, const void *data, size_t len)
157 {
158 struct bt_monitor_hdr hdr;
159
160 if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) {
161 drop_add(opcode);
162 return;
163 }
164
165 encode_hdr(&hdr, monitor_ts_get(), opcode, len);
166
167 monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len);
168 monitor_send(data, len);
169
170 atomic_clear_bit(&flags, BT_LOG_BUSY);
171 }
172
bt_monitor_new_index(u8_t type,u8_t bus,bt_addr_t * addr,const char * name)173 void bt_monitor_new_index(u8_t type, u8_t bus, bt_addr_t *addr,
174 const char *name)
175 {
176 struct bt_monitor_new_index pkt;
177
178 pkt.type = type;
179 pkt.bus = bus;
180 memcpy(pkt.bdaddr, addr, 6);
181 strncpy(pkt.name, name, sizeof(pkt.name) - 1);
182 pkt.name[sizeof(pkt.name) - 1] = '\0';
183
184 bt_monitor_send(BT_MONITOR_NEW_INDEX, &pkt, sizeof(pkt));
185 }
186
187 #if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_LOG_PRINTK)
monitor_console_out(int c)188 static int monitor_console_out(int c)
189 {
190 static char buf[MONITOR_MSG_MAX];
191 static size_t len;
192
193 if (atomic_test_and_set_bit(&flags, BT_CONSOLE_BUSY)) {
194 return c;
195 }
196
197 if (c != '\n' && len < sizeof(buf) - 1) {
198 buf[len++] = c;
199 atomic_clear_bit(&flags, BT_CONSOLE_BUSY);
200 return c;
201 }
202
203 buf[len++] = '\0';
204
205 bt_monitor_send(BT_MONITOR_SYSTEM_NOTE, buf, len);
206 len = 0;
207
208 atomic_clear_bit(&flags, BT_CONSOLE_BUSY);
209
210 return c;
211 }
212
213 extern void __printk_hook_install(int (*fn)(int));
214 extern void __stdout_hook_install(int (*fn)(int));
215 #endif /* !CONFIG_UART_CONSOLE */
216
217 #if defined(CONFIG_HAS_DTS) && !defined(CONFIG_BT_MONITOR_ON_DEV_NAME)
218 #define CONFIG_BT_MONITOR_ON_DEV_NAME CONFIG_UART_CONSOLE_ON_DEV_NAME
219 #endif
220
221 #ifndef CONFIG_LOG_MINIMAL
222 struct monitor_log_ctx {
223 size_t total_len;
224 char msg[MONITOR_MSG_MAX];
225 };
226
monitor_log_out(u8_t * data,size_t length,void * user_data)227 static int monitor_log_out(u8_t *data, size_t length, void *user_data)
228 {
229 struct monitor_log_ctx *ctx = user_data;
230 size_t i;
231
232 for (i = 0; i < length && ctx->total_len < sizeof(ctx->msg); i++) {
233 /* With CONFIG_LOG_PRINTK the line terminator will come as
234 * as part of messages.
235 */
236 if (IS_ENABLED(CONFIG_LOG_PRINTK) &&
237 (data[i] == '\r' || data[i] == '\n')) {
238 break;
239 }
240
241 ctx->msg[ctx->total_len++] = data[i];
242 }
243
244 return length;
245 }
246
247 static u8_t buf;
248
249 LOG_OUTPUT_DEFINE(monitor_log_output, monitor_log_out, &buf, 1);
250
monitor_priority_get(u8_t log_level)251 static inline u8_t monitor_priority_get(u8_t log_level)
252 {
253 static const u8_t prios[] = {
254 [LOG_LEVEL_NONE] = 0,
255 [LOG_LEVEL_ERR] = BT_LOG_ERR,
256 [LOG_LEVEL_WRN] = BT_LOG_WARN,
257 [LOG_LEVEL_INF] = BT_LOG_INFO,
258 [LOG_LEVEL_DBG] = BT_LOG_DBG,
259 };
260
261 if (log_level < ARRAY_SIZE(prios)) {
262 return prios[log_level];
263 }
264
265 return BT_LOG_DBG;
266 }
267
monitor_log_put(const struct log_backend * const backend,struct log_msg * msg)268 static void monitor_log_put(const struct log_backend *const backend,
269 struct log_msg *msg)
270 {
271 struct bt_monitor_user_logging log;
272 struct monitor_log_ctx ctx;
273 struct bt_monitor_hdr hdr;
274 const char id[] = "bt";
275
276 log_msg_get(msg);
277
278 log_output_ctx_set(&monitor_log_output, &ctx);
279
280 ctx.total_len = 0;
281 log_output_msg_process(&monitor_log_output, msg,
282 LOG_OUTPUT_FLAG_CRLF_NONE);
283
284 if (atomic_test_and_set_bit(&flags, BT_LOG_BUSY)) {
285 drop_add(BT_MONITOR_USER_LOGGING);
286 log_msg_put(msg);
287 return;
288 }
289
290 encode_hdr(&hdr, msg->hdr.timestamp, BT_MONITOR_USER_LOGGING,
291 sizeof(log) + sizeof(id) + ctx.total_len + 1);
292
293 log.priority = monitor_priority_get(msg->hdr.ids.level);
294 log.ident_len = sizeof(id);
295
296 log_msg_put(msg);
297
298 monitor_send(&hdr, BT_MONITOR_BASE_HDR_LEN + hdr.hdr_len);
299 monitor_send(&log, sizeof(log));
300 monitor_send(id, sizeof(id));
301 monitor_send(ctx.msg, ctx.total_len);
302
303 /* Terminate the string with null */
304 uart_poll_out(monitor_dev, '\0');
305
306 atomic_clear_bit(&flags, BT_LOG_BUSY);
307 }
308
monitor_log_panic(const struct log_backend * const backend)309 static void monitor_log_panic(const struct log_backend *const backend)
310 {
311 }
312
monitor_log_init(void)313 static void monitor_log_init(void)
314 {
315 log_set_timestamp_func(monitor_ts_get, MONITOR_TS_FREQ);
316 }
317
318 static const struct log_backend_api monitor_log_api = {
319 .put = monitor_log_put,
320 .panic = monitor_log_panic,
321 .init = monitor_log_init,
322 };
323
324 LOG_BACKEND_DEFINE(bt_monitor, monitor_log_api, true);
325 #endif /* CONFIG_LOG_MINIMAL */
326
bt_monitor_init(struct device * d)327 static int bt_monitor_init(struct device *d)
328 {
329 ARG_UNUSED(d);
330
331 monitor_dev = device_get_binding(CONFIG_BT_MONITOR_ON_DEV_NAME);
332
333 __ASSERT_NO_MSG(monitor_dev);
334
335 #if defined(CONFIG_UART_INTERRUPT_DRIVEN)
336 uart_irq_rx_disable(monitor_dev);
337 uart_irq_tx_disable(monitor_dev);
338 #endif
339
340 #if !defined(CONFIG_UART_CONSOLE) && !defined(CONFIG_LOG_PRINTK)
341 __printk_hook_install(monitor_console_out);
342 __stdout_hook_install(monitor_console_out);
343 #endif
344
345 return 0;
346 }
347
348 SYS_INIT(bt_monitor_init, PRE_KERNEL_1, MONITOR_INIT_PRIORITY);
349 #endif