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