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
frontend_only(void)222 static bool frontend_only(void)
223 {
224 return NO_BACKENDS || IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY);
225 }
226
227 /*
228 * Test is using 2 backends and runtime filtering is enabled. After first call
229 * filtering for backend2 is reduced to warning. It is expected that next INFO
230 * level log message will be passed only to backend1.
231 */
ZTEST(test_log_api,test_log_backend_runtime_filtering)232 ZTEST(test_log_api, test_log_backend_runtime_filtering)
233 {
234 uint16_t s_id = LOG_CURRENT_MODULE_ID();
235 uint8_t d_id = Z_LOG_LOCAL_DOMAIN_ID;
236 log_timestamp_t exp_ts = TIMESTAMP_INIT_VAL;
237
238 if (!IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
239 ztest_test_skip();
240 }
241
242 log_setup(true);
243
244 if (dbg_enabled()) {
245 char str[128];
246
247 /* If prefix is enabled, add function name prefix */
248 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
249 snprintk(str, sizeof(str),
250 "%s: test", __func__);
251 } else {
252 snprintk(str, sizeof(str), "test");
253 }
254
255 mock_log_frontend_record(s_id, LOG_LEVEL_DBG, str);
256 if (!frontend_only()) {
257 mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_DBG, exp_ts, str);
258 mock_log_backend_record(&backend2, s_id, d_id, LOG_LEVEL_DBG, exp_ts, str);
259 }
260 exp_ts++;
261 }
262
263 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
264 if (!frontend_only()) {
265 mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_INF, exp_ts, "test");
266 mock_log_backend_record(&backend2, s_id, d_id, LOG_LEVEL_INF, exp_ts, "test");
267 }
268 exp_ts++;
269
270 LOG_DBG("test");
271 LOG_INF("test");
272
273 process_and_validate(true, false);
274
275 uint32_t exp_level1 = dbg_enabled() ? LOG_LEVEL_DBG : LOG_LEVEL_INF;
276 uint32_t exp_level2 = LOG_LEVEL_WRN;
277
278 uint32_t b_level;
279 uint32_t f_level;
280
281 /* Validate levels before changing for backend2 and frontend */
282 if (!frontend_only()) {
283 b_level = log_filter_get(&backend1, d_id, s_id, true);
284 zassert_equal(b_level, exp_level1);
285
286 b_level = log_filter_get(&backend2, d_id, s_id, true);
287 zassert_equal(b_level, exp_level1);
288 }
289
290 if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
291 f_level = log_frontend_filter_get(s_id, true);
292 zassert_equal(f_level, exp_level1);
293
294 log_frontend_filter_set(s_id, LOG_LEVEL_WRN);
295
296 f_level = log_frontend_filter_get(s_id, true);
297 zassert_equal(f_level, exp_level2);
298 }
299
300 if (!frontend_only()) {
301 log_filter_set(&backend2, d_id, s_id, LOG_LEVEL_WRN);
302
303 b_level = log_filter_get(&backend1, d_id, s_id, true);
304 zassert_equal(b_level, exp_level1);
305
306 b_level = log_filter_get(&backend2, d_id, s_id, true);
307 zassert_equal(b_level, exp_level2);
308 }
309
310 uint8_t data[] = {1, 2, 4, 5, 6, 8};
311
312 if (!frontend_only()) {
313 /* INF logs expected only on backend1 */
314 mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_INF, exp_ts++, "test");
315
316 mock_log_backend_generic_record(&backend1, s_id, d_id, LOG_LEVEL_INF,
317 exp_ts++, "hexdump", data, sizeof(data));
318 }
319
320 /* WRN message expected on backends and frontend */
321 mock_log_frontend_record(s_id, LOG_LEVEL_WRN, "test2");
322 if (!frontend_only()) {
323 mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_WRN, exp_ts, "test2");
324 mock_log_backend_record(&backend2, s_id, d_id, LOG_LEVEL_WRN, exp_ts++, "test2");
325 }
326
327 mock_log_frontend_generic_record(s_id, d_id, LOG_LEVEL_WRN, "hexdump", data, sizeof(data));
328 if (!frontend_only()) {
329 mock_log_backend_generic_record(&backend1, s_id, d_id, LOG_LEVEL_WRN,
330 exp_ts, "hexdump", data, sizeof(data));
331 mock_log_backend_generic_record(&backend2, s_id, d_id, LOG_LEVEL_WRN,
332 exp_ts++, "hexdump", data, sizeof(data));
333 }
334
335 LOG_INF("test");
336 LOG_HEXDUMP_INF(data, sizeof(data), "hexdump");
337 LOG_WRN("test2");
338 LOG_HEXDUMP_WRN(data, sizeof(data), "hexdump");
339
340 process_and_validate(true, false);
341 }
342
get_max_hexdump(void)343 static size_t get_max_hexdump(void)
344 {
345 return CONFIG_LOG_BUFFER_SIZE - sizeof(struct log_msg_hdr);
346 }
347
348 #if defined(CONFIG_ARCH_POSIX)
349 #define STR_SIZE(s) (strlen(s) + 2 * sizeof(char))
350 #else
351 #define STR_SIZE(s) 0
352 #endif
353
get_long_hexdump(void)354 static size_t get_long_hexdump(void)
355 {
356 size_t extra_msg_sz = 0;
357 size_t extra_hexdump_sz = 0;
358
359 if (IS_ENABLED(CONFIG_LOG_USE_TAGGED_ARGUMENTS)) {
360 /* First message with 2 arguments => 2 tags */
361 extra_msg_sz = 2 * sizeof(int);
362
363 /*
364 * Hexdump with an implicit "%s" and the "hexdump" string
365 * as argument => 1 tag.
366 */
367 extra_hexdump_sz = sizeof(int);
368 }
369
370 return CONFIG_LOG_BUFFER_SIZE -
371 /* First message */
372 ROUND_UP(LOG_SIMPLE_MSG_LEN + 2 * sizeof(int) + extra_msg_sz,
373 CBPRINTF_PACKAGE_ALIGNMENT) -
374 /* Hexdump message excluding data */
375 ROUND_UP(LOG_SIMPLE_MSG_LEN + STR_SIZE("hexdump") + extra_hexdump_sz,
376 CBPRINTF_PACKAGE_ALIGNMENT);
377 }
378
379 /*
380 * When LOG_MODE_OVERFLOW is enabled, logger should discard oldest messages when
381 * there is no room. However, if after discarding all messages there is still no
382 * room then current log is discarded.
383 */
384 static uint8_t log_buf[CONFIG_LOG_BUFFER_SIZE];
385
ZTEST(test_log_api,test_log_overflow)386 ZTEST(test_log_api, test_log_overflow)
387 {
388 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
389
390 log_setup(false);
391
392 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
393 ztest_test_skip();
394 }
395
396 if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
397 ztest_test_skip();
398 }
399
400 for (int i = 0; i < CONFIG_LOG_BUFFER_SIZE; i++) {
401 log_buf[i] = i;
402 }
403
404 uint32_t hexdump_len = get_long_hexdump();
405
406 /* expect first message to be dropped */
407 exp_timestamp++;
408 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test 100 100");
409 mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
410 LOG_LEVEL_INF, "hexdump", log_buf, hexdump_len);
411 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test2");
412 mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
413 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
414 exp_timestamp++, "hexdump",
415 log_buf, hexdump_len);
416 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
417 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
418 exp_timestamp++, "test2");
419 mock_log_backend_drop_record(&backend1, 1);
420
421 LOG_INF("test %d %d", 100, 100);
422 LOG_HEXDUMP_INF(log_buf, hexdump_len, "hexdump");
423 LOG_INF("test2");
424
425 process_and_validate(false, false);
426
427 log_setup(false);
428
429 exp_timestamp = TIMESTAMP_INIT_VAL;
430 hexdump_len = get_max_hexdump();
431 mock_log_backend_reset(&backend1);
432 mock_log_frontend_reset();
433
434 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
435 mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
436 LOG_LEVEL_INF, "test", log_buf, hexdump_len + 1);
437 /* Log2 allocation is not destructive if request exceeds the
438 * capacity.
439 */
440 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
441 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
442 exp_timestamp, "test");
443 mock_log_backend_drop_record(&backend1, 1);
444
445 LOG_INF("test");
446 LOG_HEXDUMP_INF(log_buf, hexdump_len + 1, "test");
447
448 process_and_validate(false, false);
449
450 }
451
452 /*
453 * Test checks if arguments are correctly processed by the logger.
454 *
455 * Log messages with supported number of messages are called. Test backend and
456 * frontend validate number of arguments and values.
457 */
458 #define MOCK_LOG_FRONT_BACKEND_RECORD(str) do { \
459 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(), \
460 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF, \
461 exp_timestamp++, str); \
462 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, str); \
463 } while (0)
464
ZTEST(test_log_api,test_log_arguments)465 ZTEST(test_log_api, test_log_arguments)
466 {
467 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
468
469 log_setup(false);
470
471 MOCK_LOG_FRONT_BACKEND_RECORD("test");
472 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3");
473 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4");
474 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5");
475
476 LOG_INF("test");
477 LOG_INF("test %d %d %d", 1, 2, 3);
478 LOG_INF("test %d %d %d %d", 1, 2, 3, 4);
479 LOG_INF("test %d %d %d %d %d", 1, 2, 3, 4, 5);
480
481 process_and_validate(false, false);
482
483 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6");
484 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7");
485 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8");
486 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9");
487
488 LOG_INF("test %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6);
489 LOG_INF("test %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7);
490 LOG_INF("test %d %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7, 8);
491 LOG_INF("test %d %d %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7, 8, 9);
492
493 process_and_validate(false, false);
494
495 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10");
496 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11");
497
498 LOG_INF("test %d %d %d %d %d %d %d %d %d %d",
499 1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
500 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d",
501 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11);
502
503 process_and_validate(false, false);
504
505 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12");
506 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12 13");
507
508 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d",
509 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12);
510
511 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d %d",
512 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13);
513
514 process_and_validate(false, false);
515
516 MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12 13 14");
517 LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d %d %d",
518 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14);
519
520 process_and_validate(false, false);
521 }
522
523 /* Function comes from the file which is part of test module. It is
524 * expected that logs coming from it will have same source_id as current
525 * module (this file).
526 */
ZTEST(test_log_api,test_log_from_declared_module)527 ZTEST(test_log_api, test_log_from_declared_module)
528 {
529 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
530
531 log_setup(false);
532
533 /* See test module for log message content. */
534 if (dbg_enabled()) {
535 char str[128];
536
537 /* If prefix is enabled, add function name prefix */
538 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
539 snprintk(str, sizeof(str),
540 "%s: " TEST_DBG_MSG, "test_func");
541 } else {
542 snprintk(str, sizeof(str), TEST_DBG_MSG);
543 }
544
545 mock_log_frontend_record(test_source_id, LOG_LEVEL_DBG, str);
546 mock_log_backend_record(&backend1, test_source_id,
547 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
548 exp_timestamp++, str);
549 }
550
551 mock_log_frontend_record(test_source_id, LOG_LEVEL_ERR, TEST_ERR_MSG);
552 mock_log_backend_record(&backend1, test_source_id,
553 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
554 exp_timestamp++, TEST_ERR_MSG);
555
556 test_func();
557
558 if (dbg_enabled()) {
559 char str[128];
560
561 /* If prefix is enabled, add function name prefix */
562 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
563 snprintk(str, sizeof(str),
564 "%s: " TEST_INLINE_DBG_MSG, "test_inline_func");
565 } else {
566 snprintk(str, sizeof(str), TEST_INLINE_DBG_MSG);
567 }
568
569 mock_log_frontend_record(test_source_id, LOG_LEVEL_DBG, str);
570 mock_log_backend_record(&backend1, test_source_id,
571 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
572 exp_timestamp++, str);
573 }
574
575 mock_log_frontend_record(test_source_id, LOG_LEVEL_ERR, TEST_INLINE_ERR_MSG);
576 mock_log_backend_record(&backend1, test_source_id,
577 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
578 exp_timestamp, TEST_INLINE_ERR_MSG);
579
580 test_inline_func();
581
582 process_and_validate(false, false);
583
584 }
585
586 /** Calculate how many messages will fit in the buffer. Also calculate if
587 * remaining free space is size of message or not. This impacts how many messages
588 * are dropped. If free space is equal to message size then when buffer is full,
589 * adding new message will lead to one message drop, otherwise 2 message will
590 * be dropped.
591 */
get_short_msg_capacity(void)592 static size_t get_short_msg_capacity(void)
593 {
594 return CONFIG_LOG_BUFFER_SIZE / LOG_SIMPLE_MSG_LEN;
595 }
596
log_n_messages(uint32_t n_msg,uint32_t exp_dropped)597 static void log_n_messages(uint32_t n_msg, uint32_t exp_dropped)
598 {
599 printk("ex dropped:%d\n", exp_dropped);
600 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
601
602 log_setup(false);
603
604 stamp = TIMESTAMP_INIT_VAL;
605
606 for (uint32_t i = 0; i < n_msg; i++) {
607 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "dummy");
608 if (i >= exp_dropped) {
609 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
610 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
611 exp_timestamp, "dummy");
612 }
613 exp_timestamp++;
614 LOG_INF("dummy");
615 }
616
617 mock_log_backend_drop_record(&backend1, exp_dropped);
618
619 process_and_validate(false, false);
620 mock_log_backend_reset(&backend1);
621 }
622
623 /*
624 * Test checks if backend receives notification about dropped messages. It
625 * first blocks threads to ensure full control of log processing time and
626 * then logs certain log messages, expecting dropped notification.
627 *
628 * With multiple cpus you may not get consistent message dropping
629 * as other core may process logs. Executing on 1 cpu only.
630 */
ZTEST(test_log_api_1cpu,test_log_msg_dropped_notification)631 ZTEST(test_log_api_1cpu, test_log_msg_dropped_notification)
632 {
633 log_setup(false);
634
635 if (IS_ENABLED(CONFIG_SMP)) {
636 /* With smp you may not get consistent message dropping as other
637 * core may process logs.
638 */
639 ztest_test_skip();
640 }
641
642 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
643 ztest_test_skip();
644 }
645
646 if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
647 ztest_test_skip();
648 }
649
650 uint32_t capacity = get_short_msg_capacity();
651
652 log_n_messages(capacity, 0);
653
654 /* Expect messages dropped when logger more than buffer capacity. */
655 log_n_messages(capacity + 1, 1);
656 log_n_messages(capacity + 2, 2);
657 }
658
659 /* Test checks if panic is correctly executed. On panic logger should flush all
660 * messages and process logs in place (not in deferred way).
661 */
ZTEST(test_log_api,test_log_panic)662 ZTEST(test_log_api, test_log_panic)
663 {
664 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
665
666 log_setup(false);
667
668 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
669 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
670 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
671 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
672 exp_timestamp++, "test");
673 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
674 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
675 exp_timestamp++, "test");
676 LOG_WRN("test");
677 LOG_WRN("test");
678
679 /* logs should be flushed in panic */
680 log_panic();
681
682 process_and_validate(false, true);
683
684 /* messages processed where called */
685 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
686 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
687 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
688 exp_timestamp++, "test");
689 LOG_WRN("test");
690
691 process_and_validate(false, true);
692 }
693
ZTEST(test_log_api,test_log_printk)694 ZTEST(test_log_api, test_log_printk)
695 {
696 if (!IS_ENABLED(CONFIG_LOG_PRINTK)) {
697 ztest_test_skip();
698 }
699
700 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
701
702 log_setup(false);
703
704 mock_log_backend_record(&backend1, 0,
705 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
706 exp_timestamp++, "test 100");
707 printk("test %d", 100);
708
709 log_panic();
710
711 mock_log_backend_record(&backend1, 0,
712 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
713 exp_timestamp++, "test 101");
714 printk("test %d", 101);
715
716 process_and_validate(false, true);
717 }
718
ZTEST(test_log_api,test_log_printk_vs_raw)719 ZTEST(test_log_api, test_log_printk_vs_raw)
720 {
721 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
722
723 log_setup(false);
724
725 mock_log_frontend_record(0, LOG_LEVEL_INTERNAL_RAW_STRING, "test 100\n");
726 mock_log_backend_record(&backend1, 0,
727 CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
728 exp_timestamp++, "test 100\n");
729 LOG_PRINTK("test %d\n", 100);
730
731
732 mock_log_frontend_record(1, LOG_LEVEL_INTERNAL_RAW_STRING, "test 100\n");
733 mock_log_backend_record(&backend1, 1,
734 CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
735 exp_timestamp++, "test 100\n");
736 LOG_RAW("test %d\n", 100);
737
738
739 process_and_validate(false, false);
740 }
741
ZTEST(test_log_api,test_log_arg_evaluation)742 ZTEST(test_log_api, test_log_arg_evaluation)
743 {
744 char str[128];
745 #define TEST_MSG_0 "%u %u"
746 #define TEST_MSG_0_PREFIX "%s: %u %u"
747 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
748 uint32_t cnt0 = 0;
749 uint32_t cnt1 = 0;
750 uint32_t exp0 = 1;
751 uint32_t exp1 = 1;
752
753 log_setup(false);
754
755 if (dbg_enabled()) {
756 /* Debug message arguments are only evaluated when this level
757 * is enabled.
758 */
759 exp0++;
760 exp1++;
761 }
762
763 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "0 0");
764 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
765 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
766 exp_timestamp++, "0 0");
767 if (dbg_enabled()) {
768 /* If prefix is enabled, add function name prefix */
769 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
770 snprintk(str, sizeof(str),
771 TEST_MSG_0_PREFIX, __func__, 1, 1);
772 } else {
773 snprintk(str, sizeof(str), TEST_MSG_0, 1, 1);
774 }
775 mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_DBG, str);
776 mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
777 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
778 exp_timestamp++, str);
779 }
780 /* Arguments used for logging shall be evaluated only once. They should
781 * be evaluated also when given log level is disabled.
782 */
783 LOG_INF("%u %u", cnt0++, cnt1++);
784 LOG_DBG("%u %u", cnt0++, cnt1++);
785
786 zassert_equal(cnt0, exp0, "Got:%u, Expected:%u", cnt0, exp0);
787 zassert_equal(cnt1, exp1, "Got:%u, Expected:%u", cnt1, exp1);
788
789 process_and_validate(false, false);
790 #undef TEST_MSG_0
791 #undef TEST_MSG_0_PREFIX
792 }
793
ZTEST(test_log_api,test_log_override_level)794 ZTEST(test_log_api, test_log_override_level)
795 {
796 log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
797
798 log_setup(false);
799
800 if (CONFIG_LOG_OVERRIDE_LEVEL == 4) {
801 char str[128];
802
803 /* If prefix is enabled, add function name prefix */
804 if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
805 snprintk(str, sizeof(str),
806 "%s: " TEST_DBG_MSG, "test_func");
807 } else {
808 snprintk(str, sizeof(str), TEST_DBG_MSG);
809 }
810
811 mock_log_frontend_record(test2_source_id, LOG_LEVEL_DBG, str);
812 mock_log_backend_record(&backend1, test2_source_id,
813 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
814 exp_timestamp++, str);
815
816 mock_log_frontend_record(test2_source_id, LOG_LEVEL_ERR, TEST_ERR_MSG);
817 mock_log_backend_record(&backend1, test2_source_id,
818 Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
819 exp_timestamp++, TEST_ERR_MSG);
820 } else if (CONFIG_LOG_OVERRIDE_LEVEL != 0) {
821 zassert_true(false, "Unexpected configuration.");
822 }
823
824 test_func2();
825
826 process_and_validate(false, false);
827 }
828
829 /* Disable backends because same suite may be executed again but compiled by C++ */
log_api_suite_teardown(void * data)830 static void log_api_suite_teardown(void *data)
831 {
832 ARG_UNUSED(data);
833
834 if (NO_BACKENDS) {
835 return;
836 }
837
838 log_backend_disable(&backend1);
839 log_backend_disable(&backend2);
840 }
841
log_api_suite_setup(void)842 static void *log_api_suite_setup(void)
843 {
844 PRINT("Configuration:\n");
845 PRINT("\t Mode: %s\n",
846 IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY) ? "Frontend only" :
847 (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? "Immediate" : "Deferred"));
848 PRINT("\t Frontend: %s\n",
849 IS_ENABLED(CONFIG_LOG_FRONTEND) ? "Yes" : "No");
850 PRINT("\t Runtime filtering: %s\n",
851 IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? "yes" : "no");
852 PRINT("\t Overwrite: %s\n",
853 IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW) ? "yes" : "no");
854 if (NO_BACKENDS) {
855 PRINT("\t No backends\n");
856 }
857 #if __cplusplus
858 PRINT("\t C++: yes\n");
859 #endif
860 flush_log();
861
862 return NULL;
863 }
864
log_api_suite_before(void * data)865 static void log_api_suite_before(void *data)
866 {
867 ARG_UNUSED(data);
868
869 if (NO_BACKENDS) {
870 return;
871 }
872
873 /* Flush logs and enable test backends. */
874 flush_log();
875
876 if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
877 mock_log_frontend_check_enable();
878 }
879 mock_log_backend_check_enable(&backend1);
880 mock_log_backend_check_enable(&backend2);
881 }
882
log_api_suite_before_1cpu(void * data)883 static void log_api_suite_before_1cpu(void *data)
884 {
885 ztest_simple_1cpu_before(data);
886 log_api_suite_before(data);
887 }
888
log_api_suite_after(void * data)889 static void log_api_suite_after(void *data)
890 {
891 ARG_UNUSED(data);
892 if (NO_BACKENDS) {
893 return;
894 }
895
896 /* Disable testing backends after the test. Otherwise test may fail due
897 * to unexpected log message.
898 */
899 if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
900 mock_log_frontend_check_disable();
901 }
902 mock_log_backend_check_disable(&backend1);
903 mock_log_backend_check_disable(&backend2);
904 }
905
log_api_suite_after_1cpu(void * data)906 static void log_api_suite_after_1cpu(void *data)
907 {
908 log_api_suite_after(data);
909 ztest_simple_1cpu_after(data);
910 }
911
912 ZTEST_SUITE(test_log_api, NULL, log_api_suite_setup,
913 log_api_suite_before, log_api_suite_after, log_api_suite_teardown);
914
915 /* Suite dedicated for tests that need to run on 1 cpu only. */
916 ZTEST_SUITE(test_log_api_1cpu, NULL, log_api_suite_setup,
917 log_api_suite_before_1cpu, log_api_suite_after_1cpu, log_api_suite_teardown);
918
