1 /*
2 * Copyright (c) 2018 Nordic Semiconductor ASA
3 *
4 * SPDX-License-Identifier: Apache-2.0
5 */
6
7 #include <shell/shell_log_backend.h>
8 #include <shell/shell.h>
9 #include "shell_ops.h"
10 #include <logging/log_ctrl.h>
11
12 static bool process_msg2_from_buffer(const struct shell *shell);
13
z_shell_log_backend_output_func(uint8_t * data,size_t length,void * ctx)14 int z_shell_log_backend_output_func(uint8_t *data, size_t length, void *ctx)
15 {
16 z_shell_print_stream(ctx, data, length);
17 return length;
18 }
19
msg_from_fifo(const struct shell_log_backend * backend)20 static struct log_msg *msg_from_fifo(const struct shell_log_backend *backend)
21 {
22 struct shell_log_backend_msg msg;
23 int err;
24
25 err = k_msgq_get(backend->msgq, &msg, K_NO_WAIT);
26
27 return (err == 0) ? msg.msg : NULL;
28 }
29
30 /* Set fifo clean state (in case of deferred mode). */
fifo_reset(const struct shell_log_backend * backend)31 static void fifo_reset(const struct shell_log_backend *backend)
32 {
33 if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
34 mpsc_pbuf_init(backend->mpsc_buffer,
35 backend->mpsc_buffer_config);
36 return;
37 }
38
39 /* Flush pending log messages without processing. */
40 if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
41 struct log_msg *msg;
42
43 while ((msg = msg_from_fifo(backend)) != NULL) {
44 log_msg_put(msg);
45 }
46 }
47 }
48
z_shell_log_backend_enable(const struct shell_log_backend * backend,void * ctx,uint32_t init_log_level)49 void z_shell_log_backend_enable(const struct shell_log_backend *backend,
50 void *ctx, uint32_t init_log_level)
51 {
52 int err = 0;
53
54 if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
55 const struct shell *shell;
56
57 shell = (const struct shell *)ctx;
58
59 /* Reenable transport in blocking mode */
60 err = shell->iface->api->enable(shell->iface, true);
61 }
62
63 if (err == 0) {
64 fifo_reset(backend);
65 log_backend_enable(backend->backend, ctx, init_log_level);
66 log_output_ctx_set(backend->log_output, ctx);
67 backend->control_block->dropped_cnt = 0;
68 backend->control_block->state = SHELL_LOG_BACKEND_ENABLED;
69 }
70 }
71
flush_expired_messages(const struct shell * shell)72 static void flush_expired_messages(const struct shell *shell)
73 {
74 int err;
75 struct shell_log_backend_msg msg;
76 struct k_msgq *msgq = shell->log_backend->msgq;
77 uint32_t timeout = shell->log_backend->timeout;
78 uint32_t now = k_uptime_get_32();
79
80 while (1) {
81 err = k_msgq_peek(msgq, &msg);
82
83 if (err == 0 && ((now - msg.timestamp) > timeout)) {
84 (void)k_msgq_get(msgq, &msg, K_NO_WAIT);
85 log_msg_put(msg.msg);
86
87 if (IS_ENABLED(CONFIG_SHELL_STATS)) {
88 atomic_inc(&shell->stats->log_lost_cnt);
89 }
90 } else {
91 break;
92 }
93 }
94 }
95
msg_to_fifo(const struct shell * shell,struct log_msg * msg)96 static void msg_to_fifo(const struct shell *shell,
97 struct log_msg *msg)
98 {
99 int err;
100 bool cont;
101 struct shell_log_backend_msg t_msg = {
102 .msg = msg,
103 .timestamp = k_uptime_get_32()
104 };
105
106 do {
107 cont = false;
108 err = k_msgq_put(shell->log_backend->msgq, &t_msg,
109 K_MSEC(shell->log_backend->timeout));
110
111 switch (err) {
112 case 0:
113 break;
114 case -EAGAIN:
115 case -ENOMSG:
116 {
117 /* Attempt to drop old message. */
118 flush_expired_messages(shell);
119
120 /* Retry putting message. */
121 cont = true;
122
123 break;
124 }
125 default:
126 /* Other errors are not expected. */
127 __ASSERT_NO_MSG(0);
128 break;
129 }
130 } while (cont);
131 }
132
z_shell_log_backend_disable(const struct shell_log_backend * backend)133 void z_shell_log_backend_disable(const struct shell_log_backend *backend)
134 {
135 log_backend_disable(backend->backend);
136 backend->control_block->state = SHELL_LOG_BACKEND_DISABLED;
137 }
138
msg_process(const struct log_output * log_output,struct log_msg * msg,bool colors)139 static void msg_process(const struct log_output *log_output,
140 struct log_msg *msg, bool colors)
141 {
142 uint32_t flags = LOG_OUTPUT_FLAG_LEVEL |
143 LOG_OUTPUT_FLAG_TIMESTAMP |
144 LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
145
146 if (colors) {
147 flags |= LOG_OUTPUT_FLAG_COLORS;
148 }
149
150 log_output_msg_process(log_output, msg, flags);
151 log_msg_put(msg);
152 }
153
z_shell_log_backend_process(const struct shell_log_backend * backend)154 bool z_shell_log_backend_process(const struct shell_log_backend *backend)
155 {
156 const struct shell *shell =
157 (const struct shell *)backend->backend->cb->ctx;
158 uint32_t dropped;
159 bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) &&
160 shell->ctx->internal.flags.use_colors;
161
162 dropped = atomic_set(&backend->control_block->dropped_cnt, 0);
163 if (dropped) {
164 struct shell_vt100_colors col;
165
166 if (colors) {
167 z_shell_vt100_colors_store(shell, &col);
168 z_shell_vt100_color_set(shell, SHELL_VT100_COLOR_RED);
169 }
170
171 log_output_dropped_process(backend->log_output, dropped);
172
173 if (colors) {
174 z_shell_vt100_colors_restore(shell, &col);
175 }
176 }
177
178 if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
179 return process_msg2_from_buffer(shell);
180 }
181
182 struct log_msg *msg = msg_from_fifo(backend);
183
184 if (!msg) {
185 return false;
186 }
187 msg_process(shell->log_backend->log_output, msg, colors);
188
189 return true;
190 }
191
put(const struct log_backend * const backend,struct log_msg * msg)192 static void put(const struct log_backend *const backend, struct log_msg *msg)
193 {
194 const struct shell *shell = (const struct shell *)backend->cb->ctx;
195 bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) &&
196 shell->ctx->internal.flags.use_colors;
197 struct k_poll_signal *signal;
198
199 log_msg_get(msg);
200
201 switch (shell->log_backend->control_block->state) {
202 case SHELL_LOG_BACKEND_ENABLED:
203 msg_to_fifo(shell, msg);
204
205 if (IS_ENABLED(CONFIG_MULTITHREADING)) {
206 signal = &shell->ctx->signals[SHELL_SIGNAL_LOG_MSG];
207 k_poll_signal_raise(signal, 0);
208 }
209
210 break;
211 case SHELL_LOG_BACKEND_PANIC:
212 z_shell_cmd_line_erase(shell);
213 msg_process(shell->log_backend->log_output, msg, colors);
214
215 break;
216
217 case SHELL_LOG_BACKEND_DISABLED:
218 __fallthrough;
219 default:
220 /* Discard message. */
221 log_msg_put(msg);
222 }
223 }
224
put_sync_string(const struct log_backend * const backend,struct log_msg_ids src_level,uint32_t timestamp,const char * fmt,va_list ap)225 static void put_sync_string(const struct log_backend *const backend,
226 struct log_msg_ids src_level, uint32_t timestamp,
227 const char *fmt, va_list ap)
228 {
229 const struct shell *shell = (const struct shell *)backend->cb->ctx;
230 uint32_t key;
231 uint32_t flags = LOG_OUTPUT_FLAG_LEVEL |
232 LOG_OUTPUT_FLAG_TIMESTAMP |
233 LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
234
235 if (IS_ENABLED(CONFIG_SHELL_VT100_COLORS)) {
236 flags |= LOG_OUTPUT_FLAG_COLORS;
237 }
238
239 key = irq_lock();
240 if (!z_flag_cmd_ctx_get(shell)) {
241 z_shell_cmd_line_erase(shell);
242 }
243 log_output_string(shell->log_backend->log_output, src_level, timestamp,
244 fmt, ap, flags);
245 if (!z_flag_cmd_ctx_get(shell)) {
246 z_shell_print_prompt_and_cmd(shell);
247 }
248 irq_unlock(key);
249 }
250
put_sync_hexdump(const struct log_backend * const backend,struct log_msg_ids src_level,uint32_t timestamp,const char * metadata,const uint8_t * data,uint32_t length)251 static void put_sync_hexdump(const struct log_backend *const backend,
252 struct log_msg_ids src_level, uint32_t timestamp,
253 const char *metadata, const uint8_t *data,
254 uint32_t length)
255 {
256 const struct shell *shell = (const struct shell *)backend->cb->ctx;
257 uint32_t key;
258 uint32_t flags = LOG_OUTPUT_FLAG_LEVEL |
259 LOG_OUTPUT_FLAG_TIMESTAMP |
260 LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
261
262 if (IS_ENABLED(CONFIG_SHELL_VT100_COLORS)) {
263 flags |= LOG_OUTPUT_FLAG_COLORS;
264 }
265
266 key = irq_lock();
267 if (!z_flag_cmd_ctx_get(shell)) {
268 z_shell_cmd_line_erase(shell);
269 }
270 log_output_hexdump(shell->log_backend->log_output, src_level,
271 timestamp, metadata, data, length, flags);
272 if (!z_flag_cmd_ctx_get(shell)) {
273 z_shell_print_prompt_and_cmd(shell);
274 }
275 irq_unlock(key);
276 }
277
panic(const struct log_backend * const backend)278 static void panic(const struct log_backend *const backend)
279 {
280 const struct shell *shell = (const struct shell *)backend->cb->ctx;
281 int err;
282
283 if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
284 return;
285 }
286
287 err = shell->iface->api->enable(shell->iface, true);
288
289 if (err == 0) {
290 shell->log_backend->control_block->state =
291 SHELL_LOG_BACKEND_PANIC;
292 z_flag_panic_mode_set(shell, true);
293
294 /* Move to the start of next line. */
295 z_shell_multiline_data_calc(&shell->ctx->vt100_ctx.cons,
296 shell->ctx->cmd_buff_pos,
297 shell->ctx->cmd_buff_len);
298 z_shell_op_cursor_vert_move(shell, -1);
299 z_shell_op_cursor_horiz_move(shell,
300 -shell->ctx->vt100_ctx.cons.cur_x);
301
302 if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
303 while (process_msg2_from_buffer(shell)) {
304 /* empty */
305 }
306 } else if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
307 while (z_shell_log_backend_process(
308 shell->log_backend)) {
309 /* empty */
310 }
311 }
312 } else {
313 z_shell_log_backend_disable(shell->log_backend);
314 }
315 }
316
dropped(const struct log_backend * const backend,uint32_t cnt)317 static void dropped(const struct log_backend *const backend, uint32_t cnt)
318 {
319 const struct shell *shell = (const struct shell *)backend->cb->ctx;
320 const struct shell_log_backend *log_backend = shell->log_backend;
321
322 if (IS_ENABLED(CONFIG_SHELL_STATS)) {
323 atomic_add(&shell->stats->log_lost_cnt, cnt);
324 }
325 atomic_add(&log_backend->control_block->dropped_cnt, cnt);
326 }
327
copy_to_pbuffer(struct mpsc_pbuf_buffer * mpsc_buffer,union log_msg2_generic * msg,uint32_t timeout)328 static void copy_to_pbuffer(struct mpsc_pbuf_buffer *mpsc_buffer,
329 union log_msg2_generic *msg, uint32_t timeout)
330 {
331 size_t wlen;
332 union mpsc_pbuf_generic *dst;
333
334 wlen = log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg);
335 dst = mpsc_pbuf_alloc(mpsc_buffer, wlen, K_MSEC(timeout));
336 if (!dst) {
337 /* No space to store the log */
338 return;
339 }
340
341 /* First word contains intenal mpsc packet flags and when copying
342 * those flags must be omitted.
343 */
344 uint8_t *dst_data = (uint8_t *)dst + sizeof(struct mpsc_pbuf_hdr);
345 uint8_t *src_data = (uint8_t *)msg + sizeof(struct mpsc_pbuf_hdr);
346 size_t hdr_wlen = ceiling_fraction(sizeof(struct mpsc_pbuf_hdr),
347 sizeof(uint32_t));
348
349 dst->hdr.data = msg->buf.hdr.data;
350 memcpy(dst_data, src_data, (wlen - hdr_wlen) * sizeof(uint32_t));
351
352 mpsc_pbuf_commit(mpsc_buffer, dst);
353 }
354
process_log_msg2(const struct shell * shell,const struct log_output * log_output,union log_msg2_generic * msg,bool locked,bool colors)355 static void process_log_msg2(const struct shell *shell,
356 const struct log_output *log_output,
357 union log_msg2_generic *msg,
358 bool locked, bool colors)
359 {
360 unsigned int key;
361 uint32_t flags = LOG_OUTPUT_FLAG_LEVEL |
362 LOG_OUTPUT_FLAG_TIMESTAMP |
363 LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
364
365 if (colors) {
366 flags |= LOG_OUTPUT_FLAG_COLORS;
367 }
368
369 if (locked) {
370 key = irq_lock();
371 if (!z_flag_cmd_ctx_get(shell)) {
372 z_shell_cmd_line_erase(shell);
373 }
374 }
375
376 log_output_msg2_process(log_output, &msg->log, flags);
377
378 if (locked) {
379 if (!z_flag_cmd_ctx_get(shell)) {
380 z_shell_print_prompt_and_cmd(shell);
381 }
382 irq_unlock(key);
383 }
384 }
385
process_msg2_from_buffer(const struct shell * shell)386 static bool process_msg2_from_buffer(const struct shell *shell)
387 {
388 const struct shell_log_backend *log_backend = shell->log_backend;
389 struct mpsc_pbuf_buffer *mpsc_buffer = log_backend->mpsc_buffer;
390 const struct log_output *log_output = log_backend->log_output;
391 union log_msg2_generic *msg;
392 bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) &&
393 shell->ctx->internal.flags.use_colors;
394
395 msg = (union log_msg2_generic *)mpsc_pbuf_claim(mpsc_buffer);
396 if (!msg) {
397 return false;
398 }
399
400 process_log_msg2(shell, log_output, msg, false, colors);
401
402 mpsc_pbuf_free(mpsc_buffer, &msg->buf);
403
404 return true;
405 }
406
log2_process(const struct log_backend * const backend,union log_msg2_generic * msg)407 static void log2_process(const struct log_backend *const backend,
408 union log_msg2_generic *msg)
409 {
410 const struct shell *shell = (const struct shell *)backend->cb->ctx;
411 const struct shell_log_backend *log_backend = shell->log_backend;
412 struct mpsc_pbuf_buffer *mpsc_buffer = log_backend->mpsc_buffer;
413 const struct log_output *log_output = log_backend->log_output;
414 bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) &&
415 shell->ctx->internal.flags.use_colors;
416 struct k_poll_signal *signal;
417
418 switch (shell->log_backend->control_block->state) {
419 case SHELL_LOG_BACKEND_ENABLED:
420 if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
421 process_log_msg2(shell, log_output, msg, true, colors);
422 } else {
423 copy_to_pbuffer(mpsc_buffer, msg,
424 log_backend->timeout);
425
426 if (IS_ENABLED(CONFIG_MULTITHREADING)) {
427 signal =
428 &shell->ctx->signals[SHELL_SIGNAL_LOG_MSG];
429 k_poll_signal_raise(signal, 0);
430 }
431 }
432
433 break;
434 case SHELL_LOG_BACKEND_PANIC:
435 z_shell_cmd_line_erase(shell);
436 process_log_msg2(shell, log_output, msg, true, colors);
437
438 break;
439
440 case SHELL_LOG_BACKEND_DISABLED:
441 __fallthrough;
442 default:
443 break;
444 }
445 }
446
447 const struct log_backend_api log_backend_shell_api = {
448 .process = IS_ENABLED(CONFIG_LOG2) ? log2_process : NULL,
449 .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL,
450 .put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ?
451 put_sync_string : NULL,
452 .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ?
453 put_sync_hexdump : NULL,
454 .dropped = dropped,
455 .panic = panic,
456 };
457
