1 /*
2 * Copyright (c) 2021 Nordic Semiconductor
3 *
4 * SPDX-License-Identifier: Apache-2.0
5 */
6
7 #include "mock_backend.h"
8 #include "mock_frontend.h"
9 #include "test_module.h"
10 #include <zephyr/ztest.h>
11 #include <zephyr/logging/log.h>
12 #include <zephyr/logging/log_ctrl.h>
13 #include <zephyr/sys/cbprintf.h>
14
15 #ifndef CONFIG_LOG_BUFFER_SIZE
16 #define CONFIG_LOG_BUFFER_SIZE 4
17 #endif
18
19 #ifndef NO_BACKENDS
20 #define NO_BACKENDS 0
21 #endif
22
23 LOG_MODULE_REGISTER(test, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
24
25 #ifdef CONFIG_LOG_USE_TAGGED_ARGUMENTS
26 /* The extra sizeof(int) is the end of arguments tag. */
27 #define LOG_SIMPLE_MSG_LEN \
28 ROUND_UP(sizeof(struct log_msg) + \
29 sizeof(struct cbprintf_package_hdr_ext) + \
30 sizeof(int), CBPRINTF_PACKAGE_ALIGNMENT)
31 #else
32 #define LOG_SIMPLE_MSG_LEN \
33 ROUND_UP(sizeof(struct log_msg) + \
34 sizeof(struct cbprintf_package_hdr_ext), CBPRINTF_PACKAGE_ALIGNMENT)
35 #endif
36
37 #ifdef CONFIG_LOG_TIMESTAMP_64BIT
38 #define TIMESTAMP_INIT_VAL 0x100000000
39 #else
40 #define TIMESTAMP_INIT_VAL 0
41 #endif
42
43 #if NO_BACKENDS
44 static struct log_backend backend1;
45 static struct log_backend backend2;
46 #else
47 MOCK_LOG_BACKEND_DEFINE(backend1, false);
48 MOCK_LOG_BACKEND_DEFINE(backend2, false);
49 #endif
50
51 static log_timestamp_t stamp;
52 static bool in_panic;
53 static int16_t test_source_id;
54 static int16_t test2_source_id;
55
timestamp_get(void)56 static log_timestamp_t timestamp_get(void)
57 {
58 return NO_BACKENDS ? (log_timestamp_t)UINT32_MAX : stamp++;
59 }
60
61 /**
62 * @brief Flush logs.
63 *
64 * If processing thread is enabled keep sleeping until there are no pending messages
65 * else process logs here.
66 */
flush_log(void)67 static void flush_log(void)
68 {
69 if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
70 while (log_data_pending()) {
71 k_msleep(10);
72 }
73 k_msleep(100);
74 } else {
75 while (LOG_PROCESS()) {
76 }
77 }
78 }
79
log_setup(bool backend2_enable)80 static void log_setup(bool backend2_enable)
81 {
82 stamp = TIMESTAMP_INIT_VAL;
83 zassert_false(in_panic, "Logger in panic state.");
84
85 log_core_init();
86 if (!IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
87 log_init();
88 }
89
90 zassert_equal(0, log_set_timestamp_func(timestamp_get, 0),
91 "Expects successful timestamp function setting.");
92
93 mock_log_frontend_reset();
94
95 test_source_id = log_source_id_get(STRINGIFY(test));
96 test2_source_id = log_source_id_get(STRINGIFY(test2));
97
98 if (NO_BACKENDS) {
99 return;
100 }
101
102 mock_log_backend_reset(&backend1);
103 mock_log_backend_reset(&backend2);
104
105 log_backend_enable(&backend1, backend1.cb->ctx, LOG_LEVEL_DBG);
106
107 if (backend2_enable) {
108 log_backend_enable(&backend2, backend2.cb->ctx, LOG_LEVEL_DBG);
109 } else {
110 log_backend_disable(&backend2);
111 }
112
113 }
114
115 /**
116 * @brief Process and validate that backends got expected content.
117 *
118 * @param backend2_enable If true backend2 is also validated.
119 * @param panic True means that logging is in panic mode, flushing is skipped.
120 */
process_and_validate(bool backend2_enable,bool panic)121 static void process_and_validate(bool backend2_enable, bool panic)
122 {
123 if (!panic) {
124 flush_log();
125 }
126
127 mock_log_frontend_validate(panic);
128
129 if (NO_BACKENDS) {
130 int cnt;
131
132 STRUCT_SECTION_COUNT(log_backend, &cnt);
133 zassert_equal(cnt, 0);
134 return;
135 }
136
137 if (IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY)) {
138 return;
139 }
140
141 mock_log_backend_validate(&backend1, panic);
142
143 if (backend2_enable) {
144 mock_log_backend_validate(&backend2, panic);
145 }
146 }
147
dbg_enabled(void)148 static bool dbg_enabled(void)
149 {
150 return IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG) || (CONFIG_LOG_OVERRIDE_LEVEL == 4);
151 }
152
ZTEST(test_log_api,test_log_various_messages)153 ZTEST(test_log_api, test_log_various_messages)
154 {
155 char str[128];
156 char dstr[] = "abcd";
157 int8_t i = -5;
158 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
159
160 log_setup(false);
161
162 unsigned long long ull = 0x1122334455667799;
163 long long ll = -12313213214454545;
164
165 #define TEST_MSG_0 "%lld %llu %hhd"
166 #define TEST_MSG_0_PREFIX "%s: %lld %llu %hhd"
167 #define TEST_MSG_1 "%f %d %f"
168
169 if (dbg_enabled()) {
170 /* If prefix is enabled, add function name prefix */
171 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
172 snprintk(str, sizeof(str),
173 TEST_MSG_0_PREFIX, __func__, ll, ull, i);
174 } else {
175 snprintk(str, sizeof(str), TEST_MSG_0, ll, ull, i);
176 }
177
178 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_DBG, str);
179 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
180 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
181 exp_timestamp++, str);
182 }
183
184 LOG_DBG(TEST_MSG_0, ll, ull, i);
185
186 #ifdef CONFIG_FPU
187 float f = -1.2356f;
188 double d = -1.2356;
189
190 snprintk(str, sizeof(str), TEST_MSG_1, (double)f, 100, d);
191 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, str);
192 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
193 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
194 exp_timestamp++, str);
195
196 LOG_INF(TEST_MSG_1, (double)f, 100, d);
197 #endif /* CONFIG_FPU */
198
199 snprintk(str, sizeof(str), "wrn %s", dstr);
200 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, str);
201 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
202 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
203 exp_timestamp++, str);
204
205 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_ERR, "err");
206 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
207 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
208 exp_timestamp++, "err");
209
210 LOG_WRN("wrn %s", dstr);
211 dstr[0] = '\0';
212
213 LOG_ERR("err");
214
215 process_and_validate(false, false);
216
217 #undef TEST_MSG_0
218 #undef TEST_MSG_0_PREFIX
219 #undef TEST_MSG_1
220 }
221
222 /*
223 * Test is using 2 backends and runtime filtering is enabled. After first call
224 * filtering for backend2 is reduced to warning. It is expected that next INFO
225 * level log message will be passed only to backend1.
226 */
ZTEST(test_log_api,test_log_backend_runtime_filtering)227 ZTEST(test_log_api, test_log_backend_runtime_filtering)
228 {
229 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
230
231 if (!IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
232 ztest_test_skip();
233 }
234
235 log_setup(true);
236
237 if (dbg_enabled()) {
238 char str[128];
239
240 /* If prefix is enabled, add function name prefix */
241 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
242 snprintk(str, sizeof(str),
243 "%s: test", __func__);
244 } else {
245 snprintk(str, sizeof(str), "test");
246 }
247
248 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_DBG, str);
249 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
250 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
251 exp_timestamp, str);
252 mock_log_backend_record(&backend2, LOG_CURRENT_MODULE_ID(),
253 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
254 exp_timestamp, str);
255 exp_timestamp++;
256 }
257
258 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
259 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
260 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
261 exp_timestamp, "test");
262 mock_log_backend_record(&backend2, LOG_CURRENT_MODULE_ID(),
263 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
264 exp_timestamp, "test");
265 exp_timestamp++;
266
267 LOG_DBG("test");
268 LOG_INF("test");
269
270 process_and_validate(true, false);
271
272
273 log_filter_set(&backend2,
274 Z_LOG_LOCAL_DOMAIN_ID,
275 LOG_CURRENT_MODULE_ID(),
276 LOG_LEVEL_WRN);
277
278 uint8_t data[] = {1, 2, 4, 5, 6, 8};
279
280 /* INF logs expected only on backend1 */
281 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
282 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
283 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
284 exp_timestamp++, "test");
285
286 mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
287 LOG_LEVEL_INF, "hexdump", data, sizeof(data));
288 mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
289 Z_LOG_LOCAL_DOMAIN_ID,
290 LOG_LEVEL_INF,
291 exp_timestamp++, "hexdump",
292 data, sizeof(data));
293
294 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test2");
295 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
296 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
297 exp_timestamp, "test2");
298 mock_log_backend_record(&backend2, LOG_CURRENT_MODULE_ID(),
299 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
300 exp_timestamp++, "test2");
301
302 mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
303 LOG_LEVEL_WRN, "hexdump", data, sizeof(data));
304 mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
305 Z_LOG_LOCAL_DOMAIN_ID,
306 LOG_LEVEL_WRN,
307 exp_timestamp, "hexdump",
308 data, sizeof(data));
309 mock_log_backend_generic_record(&backend2, LOG_CURRENT_MODULE_ID(),
310 Z_LOG_LOCAL_DOMAIN_ID,
311 LOG_LEVEL_WRN,
312 exp_timestamp++, "hexdump",
313 data, sizeof(data));
314
315 LOG_INF("test");
316 LOG_HEXDUMP_INF(data, sizeof(data), "hexdump");
317 LOG_WRN("test2");
318 LOG_HEXDUMP_WRN(data, sizeof(data), "hexdump");
319
320 process_and_validate(true, false);
321
322 }
323
get_max_hexdump(void)324 static size_t get_max_hexdump(void)
325 {
326 return CONFIG_LOG_BUFFER_SIZE - sizeof(struct log_msg_hdr);
327 }
328
329 #if defined(CONFIG_ARCH_POSIX)
330 #define STR_SIZE(s) (strlen(s) + 2 * sizeof(char))
331 #else
332 #define STR_SIZE(s) 0
333 #endif
334
get_long_hexdump(void)335 static size_t get_long_hexdump(void)
336 {
337 size_t extra_msg_sz = 0;
338 size_t extra_hexdump_sz = 0;
339
340 if (IS_ENABLED(CONFIG_LOG_USE_TAGGED_ARGUMENTS)) {
341 /* First message with 2 arguments => 2 tags */
342 extra_msg_sz = 2 * sizeof(int);
343
344 /*
345 * Hexdump with an implicit "%s" and the "hexdump" string
346 * as argument => 1 tag.
347 */
348 extra_hexdump_sz = sizeof(int);
349 }
350
351 return CONFIG_LOG_BUFFER_SIZE -
352 /* First message */
353 ROUND_UP(LOG_SIMPLE_MSG_LEN + 2 * sizeof(int) + extra_msg_sz,
354 CBPRINTF_PACKAGE_ALIGNMENT) -
355 /* Hexdump message excluding data */
356 ROUND_UP(LOG_SIMPLE_MSG_LEN + STR_SIZE("hexdump") + extra_hexdump_sz,
357 CBPRINTF_PACKAGE_ALIGNMENT);
358 }
359
360 /*
361 * When LOG_MODE_OVERFLOW is enabled, logger should discard oldest messages when
362 * there is no room. However, if after discarding all messages there is still no
363 * room then current log is discarded.
364 */
365 static uint8_t log_buf[CONFIG_LOG_BUFFER_SIZE];
366
ZTEST(test_log_api,test_log_overflow)367 ZTEST(test_log_api, test_log_overflow)
368 {
369 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
370
371 log_setup(false);
372
373 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
374 ztest_test_skip();
375 }
376
377 if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
378 ztest_test_skip();
379 }
380
381 for (int i = 0; i < CONFIG_LOG_BUFFER_SIZE; i++) {
382 log_buf[i] = i;
383 }
384
385 uint32_t hexdump_len = get_long_hexdump();
386
387 /* expect first message to be dropped */
388 exp_timestamp++;
389 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test 100 100");
390 mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
391 LOG_LEVEL_INF, "hexdump", log_buf, hexdump_len);
392 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test2");
393 mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
394 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
395 exp_timestamp++, "hexdump",
396 log_buf, hexdump_len);
397 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
398 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
399 exp_timestamp++, "test2");
400 mock_log_backend_drop_record(&backend1, 1);
401
402 LOG_INF("test %d %d", 100, 100);
403 LOG_HEXDUMP_INF(log_buf, hexdump_len, "hexdump");
404 LOG_INF("test2");
405
406 process_and_validate(false, false);
407
408 log_setup(false);
409
410 exp_timestamp = TIMESTAMP_INIT_VAL;
411 hexdump_len = get_max_hexdump();
412 mock_log_backend_reset(&backend1);
413 mock_log_frontend_reset();
414
415 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
416 mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
417 LOG_LEVEL_INF, "test", log_buf, hexdump_len + 1);
418 /* Log2 allocation is not destructive if request exceeds the
419 * capacity.
420 */
421 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
422 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
423 exp_timestamp, "test");
424 mock_log_backend_drop_record(&backend1, 1);
425
426 LOG_INF("test");
427 LOG_HEXDUMP_INF(log_buf, hexdump_len + 1, "test");
428
429 process_and_validate(false, false);
430
431 }
432
433 /*
434 * Test checks if arguments are correctly processed by the logger.
435 *
436 * Log messages with supported number of messages are called. Test backend and
437 * frontend validate number of arguments and values.
438 */
439 #define MOCK_LOG_FRONT_BACKEND_RECORD(str) do { \
440 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(), \
441 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF, \
442 exp_timestamp++, str); \
443 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, str); \
444 } while (0)
445
ZTEST(test_log_api,test_log_arguments)446 ZTEST(test_log_api, test_log_arguments)
447 {
448 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
449
450 log_setup(false);
451
452 MOCK_LOG_FRONT_BACKEND_RECORD("test");
453 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3");
454 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4");
455 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5");
456
457 LOG_INF("test");
458 LOG_INF("test %d %d %d", 1, 2, 3);
459 LOG_INF("test %d %d %d %d", 1, 2, 3, 4);
460 LOG_INF("test %d %d %d %d %d", 1, 2, 3, 4, 5);
461
462 process_and_validate(false, false);
463
464 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6");
465 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7");
466 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8");
467 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9");
468
469 LOG_INF("test %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6);
470 LOG_INF("test %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7);
471 LOG_INF("test %d %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7, 8);
472 LOG_INF("test %d %d %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7, 8, 9);
473
474 process_and_validate(false, false);
475
476 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10");
477 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11");
478
479 LOG_INF("test %d %d %d %d %d %d %d %d %d %d",
480 1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
481 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d",
482 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11);
483
484 process_and_validate(false, false);
485
486 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12");
487 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12 13");
488
489 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d",
490 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12);
491
492 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d %d",
493 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13);
494
495 process_and_validate(false, false);
496
497 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12 13 14");
498 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d %d %d",
499 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14);
500
501 process_and_validate(false, false);
502 }
503
504 /* Function comes from the file which is part of test module. It is
505 * expected that logs coming from it will have same source_id as current
506 * module (this file).
507 */
ZTEST(test_log_api,test_log_from_declared_module)508 ZTEST(test_log_api, test_log_from_declared_module)
509 {
510 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
511
512 log_setup(false);
513
514 /* See test module for log message content. */
515 if (dbg_enabled()) {
516 char str[128];
517
518 /* If prefix is enabled, add function name prefix */
519 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
520 snprintk(str, sizeof(str),
521 "%s: " TEST_DBG_MSG, "test_func");
522 } else {
523 snprintk(str, sizeof(str), TEST_DBG_MSG);
524 }
525
526 mock_log_frontend_record(test_source_id, LOG_LEVEL_DBG, str);
527 mock_log_backend_record(&backend1, test_source_id,
528 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
529 exp_timestamp++, str);
530 }
531
532 mock_log_frontend_record(test_source_id, LOG_LEVEL_ERR, TEST_ERR_MSG);
533 mock_log_backend_record(&backend1, test_source_id,
534 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
535 exp_timestamp++, TEST_ERR_MSG);
536
537 test_func();
538
539 if (dbg_enabled()) {
540 char str[128];
541
542 /* If prefix is enabled, add function name prefix */
543 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
544 snprintk(str, sizeof(str),
545 "%s: " TEST_INLINE_DBG_MSG, "test_inline_func");
546 } else {
547 snprintk(str, sizeof(str), TEST_INLINE_DBG_MSG);
548 }
549
550 mock_log_frontend_record(test_source_id, LOG_LEVEL_DBG, str);
551 mock_log_backend_record(&backend1, test_source_id,
552 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
553 exp_timestamp++, str);
554 }
555
556 mock_log_frontend_record(test_source_id, LOG_LEVEL_ERR, TEST_INLINE_ERR_MSG);
557 mock_log_backend_record(&backend1, test_source_id,
558 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
559 exp_timestamp, TEST_INLINE_ERR_MSG);
560
561 test_inline_func();
562
563 process_and_validate(false, false);
564
565 }
566
567 /** Calculate how many messages will fit in the buffer. Also calculate if
568 * remaining free space is size of message or not. This impacts how many messages
569 * are dropped. If free space is equal to message size then when buffer is full,
570 * adding new message will lead to one message drop, otherwise 2 message will
571 * be dropped.
572 */
get_short_msg_capacity(void)573 static size_t get_short_msg_capacity(void)
574 {
575 return CONFIG_LOG_BUFFER_SIZE / LOG_SIMPLE_MSG_LEN;
576 }
577
log_n_messages(uint32_t n_msg,uint32_t exp_dropped)578 static void log_n_messages(uint32_t n_msg, uint32_t exp_dropped)
579 {
580 printk("ex dropped:%d\n", exp_dropped);
581 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
582
583 log_setup(false);
584
585 stamp = TIMESTAMP_INIT_VAL;
586
587 for (uint32_t i = 0; i < n_msg; i++) {
588 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "dummy");
589 if (i >= exp_dropped) {
590 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
591 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
592 exp_timestamp, "dummy");
593 }
594 exp_timestamp++;
595 LOG_INF("dummy");
596 }
597
598 mock_log_backend_drop_record(&backend1, exp_dropped);
599
600 process_and_validate(false, false);
601 mock_log_backend_reset(&backend1);
602 }
603
604 /*
605 * Test checks if backend receives notification about dropped messages. It
606 * first blocks threads to ensure full control of log processing time and
607 * then logs certain log messages, expecting dropped notification.
608 *
609 * With multiple cpus you may not get consistent message dropping
610 * as other core may process logs. Executing on 1 cpu only.
611 */
ZTEST(test_log_api_1cpu,test_log_msg_dropped_notification)612 ZTEST(test_log_api_1cpu, test_log_msg_dropped_notification)
613 {
614 log_setup(false);
615
616 if (IS_ENABLED(CONFIG_SMP)) {
617 /* With smp you may not get consistent message dropping as other
618 * core may process logs.
619 */
620 ztest_test_skip();
621 }
622
623 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
624 ztest_test_skip();
625 }
626
627 if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
628 ztest_test_skip();
629 }
630
631 uint32_t capacity = get_short_msg_capacity();
632
633 log_n_messages(capacity, 0);
634
635 /* Expect messages dropped when logger more than buffer capacity. */
636 log_n_messages(capacity + 1, 1);
637 log_n_messages(capacity + 2, 2);
638 }
639
640 /* Test checks if panic is correctly executed. On panic logger should flush all
641 * messages and process logs in place (not in deferred way).
642 */
ZTEST(test_log_api,test_log_panic)643 ZTEST(test_log_api, test_log_panic)
644 {
645 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
646
647 log_setup(false);
648
649 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
650 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
651 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
652 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
653 exp_timestamp++, "test");
654 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
655 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
656 exp_timestamp++, "test");
657 LOG_WRN("test");
658 LOG_WRN("test");
659
660 /* logs should be flushed in panic */
661 log_panic();
662
663 process_and_validate(false, true);
664
665 /* messages processed where called */
666 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
667 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
668 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
669 exp_timestamp++, "test");
670 LOG_WRN("test");
671
672 process_and_validate(false, true);
673 }
674
ZTEST(test_log_api,test_log_printk)675 ZTEST(test_log_api, test_log_printk)
676 {
677 if (!IS_ENABLED(CONFIG_LOG_PRINTK)) {
678 ztest_test_skip();
679 }
680
681 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
682
683 log_setup(false);
684
685 mock_log_backend_record(&backend1, 0,
686 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
687 exp_timestamp++, "test 100");
688 printk("test %d", 100);
689
690 log_panic();
691
692 mock_log_backend_record(&backend1, 0,
693 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
694 exp_timestamp++, "test 101");
695 printk("test %d", 101);
696
697 process_and_validate(false, true);
698 }
699
ZTEST(test_log_api,test_log_printk_vs_raw)700 ZTEST(test_log_api, test_log_printk_vs_raw)
701 {
702 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
703
704 log_setup(false);
705
706 mock_log_frontend_record(0, LOG_LEVEL_INTERNAL_RAW_STRING, "test 100\n");
707 mock_log_backend_record(&backend1, 0,
708 CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
709 exp_timestamp++, "test 100\n");
710 LOG_PRINTK("test %d\n", 100);
711
712
713 mock_log_frontend_record(1, LOG_LEVEL_INTERNAL_RAW_STRING, "test 100\n");
714 mock_log_backend_record(&backend1, 1,
715 CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
716 exp_timestamp++, "test 100\n");
717 LOG_RAW("test %d\n", 100);
718
719
720 process_and_validate(false, false);
721 }
722
ZTEST(test_log_api,test_log_arg_evaluation)723 ZTEST(test_log_api, test_log_arg_evaluation)
724 {
725 char str[128];
726 #define TEST_MSG_0 "%u %u"
727 #define TEST_MSG_0_PREFIX "%s: %u %u"
728 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
729 uint32_t cnt0 = 0;
730 uint32_t cnt1 = 0;
731 uint32_t exp0 = 1;
732 uint32_t exp1 = 1;
733
734 log_setup(false);
735
736 if (dbg_enabled()) {
737 /* Debug message arguments are only evaluated when this level
738 * is enabled.
739 */
740 exp0++;
741 exp1++;
742 }
743
744 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "0 0");
745 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
746 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
747 exp_timestamp++, "0 0");
748 if (dbg_enabled()) {
749 /* If prefix is enabled, add function name prefix */
750 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
751 snprintk(str, sizeof(str),
752 TEST_MSG_0_PREFIX, __func__, 1, 1);
753 } else {
754 snprintk(str, sizeof(str), TEST_MSG_0, 1, 1);
755 }
756 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_DBG, str);
757 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
758 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
759 exp_timestamp++, str);
760 }
761 /* Arguments used for logging shall be evaluated only once. They should
762 * be evaluated also when given log level is disabled.
763 */
764 LOG_INF("%u %u", cnt0++, cnt1++);
765 LOG_DBG("%u %u", cnt0++, cnt1++);
766
767 zassert_equal(cnt0, exp0, "Got:%u, Expected:%u", cnt0, exp0);
768 zassert_equal(cnt1, exp1, "Got:%u, Expected:%u", cnt1, exp1);
769
770 process_and_validate(false, false);
771 #undef TEST_MSG_0
772 #undef TEST_MSG_0_PREFIX
773 }
774
ZTEST(test_log_api,test_log_override_level)775 ZTEST(test_log_api, test_log_override_level)
776 {
777 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
778
779 log_setup(false);
780
781 if (CONFIG_LOG_OVERRIDE_LEVEL == 4) {
782 char str[128];
783
784 /* If prefix is enabled, add function name prefix */
785 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
786 snprintk(str, sizeof(str),
787 "%s: " TEST_DBG_MSG, "test_func");
788 } else {
789 snprintk(str, sizeof(str), TEST_DBG_MSG);
790 }
791
792 mock_log_frontend_record(test2_source_id, LOG_LEVEL_DBG, str);
793 mock_log_backend_record(&backend1, test2_source_id,
794 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
795 exp_timestamp++, str);
796
797 mock_log_frontend_record(test2_source_id, LOG_LEVEL_ERR, TEST_ERR_MSG);
798 mock_log_backend_record(&backend1, test2_source_id,
799 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
800 exp_timestamp++, TEST_ERR_MSG);
801 } else if (CONFIG_LOG_OVERRIDE_LEVEL != 0) {
802 zassert_true(false, "Unexpected configuration.");
803 }
804
805 test_func2();
806
807 process_and_validate(false, false);
808 }
809
810 /* Disable backends because same suite may be executed again but compiled by C++ */
log_api_suite_teardown(void * data)811 static void log_api_suite_teardown(void *data)
812 {
813 ARG_UNUSED(data);
814
815 if (NO_BACKENDS) {
816 return;
817 }
818
819 log_backend_disable(&backend1);
820 log_backend_disable(&backend2);
821 }
822
log_api_suite_setup(void)823 static void *log_api_suite_setup(void)
824 {
825 PRINT("Configuration:\n");
826 PRINT("\t Mode: %s\n",
827 IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY) ? "Frontend only" :
828 (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? "Immediate" : "Deferred"));
829 PRINT("\t Frontend: %s\n",
830 IS_ENABLED(CONFIG_LOG_FRONTEND) ? "Yes" : "No");
831 PRINT("\t Runtime filtering: %s\n",
832 IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? "yes" : "no");
833 PRINT("\t Overwrite: %s\n",
834 IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW) ? "yes" : "no");
835 if (NO_BACKENDS) {
836 PRINT("\t No backends\n");
837 }
838 #if __cplusplus
839 PRINT("\t C++: yes\n");
840 #endif
841 flush_log();
842
843 return NULL;
844 }
845
log_api_suite_before(void * data)846 static void log_api_suite_before(void *data)
847 {
848 ARG_UNUSED(data);
849
850 if (NO_BACKENDS) {
851 return;
852 }
853
854 /* Flush logs and enable test backends. */
855 flush_log();
856
857 if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
858 mock_log_frontend_check_enable();
859 }
860 mock_log_backend_check_enable(&backend1);
861 mock_log_backend_check_enable(&backend2);
862 }
863
log_api_suite_before_1cpu(void * data)864 static void log_api_suite_before_1cpu(void *data)
865 {
866 ztest_simple_1cpu_before(data);
867 log_api_suite_before(data);
868 }
869
log_api_suite_after(void * data)870 static void log_api_suite_after(void *data)
871 {
872 ARG_UNUSED(data);
873 if (NO_BACKENDS) {
874 return;
875 }
876
877 /* Disable testing backends after the test. Otherwise test may fail due
878 * to unexpected log message.
879 */
880 if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
881 mock_log_frontend_check_disable();
882 }
883 mock_log_backend_check_disable(&backend1);
884 mock_log_backend_check_disable(&backend2);
885 }
886
log_api_suite_after_1cpu(void * data)887 static void log_api_suite_after_1cpu(void *data)
888 {
889 log_api_suite_after(data);
890 ztest_simple_1cpu_after(data);
891 }
892
893 ZTEST_SUITE(test_log_api, NULL, log_api_suite_setup,
894 log_api_suite_before, log_api_suite_after, log_api_suite_teardown);
895
896 /* Suite dedicated for tests that need to run on 1 cpu only. */
897 ZTEST_SUITE(test_log_api_1cpu, NULL, log_api_suite_setup,
898 log_api_suite_before_1cpu, log_api_suite_after_1cpu, log_api_suite_teardown);
899
