1 /*
2 * Copyright (c) 2018 Nordic Semiconductor
3 *
4 * SPDX-License-Identifier: Apache-2.0
5 */
6
7 /**
8 * @file
9 * @brief Test log message
10 */
11
12 #include <zephyr/logging/log_msg.h>
13 #include <zephyr/logging/log_internal.h>
14 #include <zephyr/logging/log_ctrl.h>
15
16 #include <zephyr/tc_util.h>
17 #include <stdbool.h>
18 #include <zephyr/kernel.h>
19 #include <zephyr/ztest.h>
20 #include <zephyr/sys/cbprintf.h>
21
22 #if CONFIG_NO_OPTIMIZATIONS
23 #define EXP_MODE(name) Z_LOG_MSG_MODE_RUNTIME
24 #else
25 #define EXP_MODE(name) Z_LOG_MSG_MODE_##name
26 #endif
27
28 #define TEST_TIMESTAMP_INIT_VALUE \
29 COND_CODE_1(CONFIG_LOG_TIMESTAMP_64BIT, (0x1234123412), (0x11223344))
30
31 static log_timestamp_t timestamp;
32
get_timestamp(void)33 log_timestamp_t get_timestamp(void)
34 {
35 return timestamp;
36 }
37
test_init(void)38 static void test_init(void)
39 {
40 timestamp = TEST_TIMESTAMP_INIT_VALUE;
41 z_log_msg_init();
42 log_set_timestamp_func(get_timestamp, 0);
43 }
44
print_msg(struct log_msg * msg)45 void print_msg(struct log_msg *msg)
46 {
47 printk("-----------------------printing message--------------------\n");
48 printk("message %p\n", msg);
49 printk("package len: %d, data len: %d\n",
50 msg->hdr.desc.package_len,
51 msg->hdr.desc.data_len);
52 for (int i = 0; i < msg->hdr.desc.package_len; i++) {
53 printk("%02x ", msg->data[i]);
54 }
55 printk("\n");
56 printk("source: %p\n", msg->hdr.source);
57 printk("timestamp: %d\n", (int)msg->hdr.timestamp);
58 printk("-------------------end of printing message-----------------\n");
59 }
60
61 struct test_buf {
62 char *buf;
63 int idx;
64 };
65
out(int c,void * ctx)66 int out(int c, void *ctx)
67 {
68 struct test_buf *t = ctx;
69
70 t->buf[t->idx++] = c;
71
72 return c;
73 }
74
basic_validate(struct log_msg * msg,const struct log_source_const_data * source,uint8_t domain,uint8_t level,log_timestamp_t t,const void * data,size_t data_len,char * str)75 static void basic_validate(struct log_msg *msg,
76 const struct log_source_const_data *source,
77 uint8_t domain, uint8_t level, log_timestamp_t t,
78 const void *data, size_t data_len, char *str)
79 {
80 int rv;
81 uint8_t *d;
82 size_t len = 0;
83 char buf[256];
84 struct test_buf tbuf = { .buf = buf, .idx = 0 };
85
86 zassert_equal(log_msg_get_source(msg), (void *)source);
87 zassert_equal(log_msg_get_domain(msg), domain);
88 zassert_equal(log_msg_get_level(msg), level);
89 zassert_equal(log_msg_get_timestamp(msg), t);
90
91 d = log_msg_get_data(msg, &len);
92 zassert_equal(len, data_len);
93 if (len) {
94 rv = memcmp(d, data, data_len);
95 zassert_equal(rv, 0);
96 }
97
98 d = log_msg_get_package(msg, &len);
99 if (str) {
100 rv = cbpprintf(out, &tbuf, d);
101 zassert_true(rv > 0);
102 buf[rv] = '\0';
103
104 rv = strncmp(buf, str, sizeof(buf));
105 zassert_equal(rv, 0, "expected:\n%s,\ngot:\n%s", str, buf);
106 }
107 }
108
msg_copy_and_free(union log_msg_generic * msg,uint8_t * buf,size_t buf_len)109 union log_msg_generic *msg_copy_and_free(union log_msg_generic *msg,
110 uint8_t *buf, size_t buf_len)
111 {
112 size_t len = sizeof(int) *
113 log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg);
114
115 zassert_true(len < buf_len);
116
117 memcpy(buf, msg, len);
118
119 z_log_msg_free(msg);
120
121 return (union log_msg_generic *)buf;
122 }
123
clear_pkg_flags(struct log_msg * msg)124 void clear_pkg_flags(struct log_msg *msg)
125 {
126 #ifdef CONFIG_CBPRINTF_PACKAGE_HEADER_STORE_CREATION_FLAGS
127 /*
128 * The various tests create cbprintf packages differently
129 * for the same log message. This results in different
130 * package flags stored in those packages. These package
131 * flags can be ignored as we only want to make sure
132 * the remaining header bits, the format string, and
133 * the format arguments are all the same.
134 */
135
136 uint8_t *d;
137 size_t len;
138
139 d = log_msg_get_package(msg, &len);
140 if (len > 0) {
141 union cbprintf_package_hdr *hdr = (void *)d;
142
143 hdr->desc.pkg_flags = 0U;
144 }
145 #else
146 ARG_UNUSED(msg);
147 #endif
148 }
149
validate_base_message_set(const struct log_source_const_data * source,uint8_t domain,uint8_t level,log_timestamp_t t,const void * data,size_t data_len,char * str)150 void validate_base_message_set(const struct log_source_const_data *source,
151 uint8_t domain, uint8_t level,
152 log_timestamp_t t, const void *data,
153 size_t data_len, char *str)
154 {
155 uint8_t __aligned(Z_LOG_MSG_ALIGNMENT) buf0[256];
156 uint8_t __aligned(Z_LOG_MSG_ALIGNMENT) buf1[256];
157 uint8_t __aligned(Z_LOG_MSG_ALIGNMENT) buf2[256];
158 size_t len0, len1, len2;
159 union log_msg_generic *msg0, *msg1, *msg2;
160
161 msg0 = z_log_msg_claim(NULL);
162 zassert_true(msg0, "Unexpected null message");
163 len0 = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg0);
164 msg0 = msg_copy_and_free(msg0, buf0, sizeof(buf0));
165 clear_pkg_flags(&msg0->log);
166
167 msg1 = z_log_msg_claim(NULL);
168 zassert_true(msg1, "Unexpected null message");
169 len1 = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg1);
170 msg1 = msg_copy_and_free(msg1, buf1, sizeof(buf1));
171 clear_pkg_flags(&msg1->log);
172
173 msg2 = z_log_msg_claim(NULL);
174 zassert_true(msg2, "Unexpected null message");
175 len2 = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg2);
176 msg2 = msg_copy_and_free(msg2, buf2, sizeof(buf2));
177 clear_pkg_flags(&msg2->log);
178
179 print_msg(&msg0->log);
180 print_msg(&msg1->log);
181 print_msg(&msg2->log);
182
183 /* Messages created with static packaging should have same output.
184 * Runtime created message (msg2) may have strings copied in and thus
185 * different length.
186 */
187 zassert_equal(len0, len1);
188
189 int rv = memcmp(msg0, msg1, sizeof(int) * len0);
190
191 zassert_equal(rv, 0, "Unexpected memcmp result: %d", rv);
192
193 /* msg1 is not validated because it should be the same as msg0. */
194 basic_validate(&msg0->log, source, domain, level,
195 t, data, data_len, str);
196 basic_validate(&msg2->log, source, domain, level,
197 t, data, data_len, str);
198 }
199
ZTEST(log_msg,test_log_msg_0_args_msg)200 ZTEST(log_msg, test_log_msg_0_args_msg)
201 {
202 #undef TEST_MSG
203 #define TEST_MSG "0 args"
204 static const uint8_t domain = 3;
205 static const uint8_t level = 2;
206 const void *source = (const void *)123;
207 int mode;
208
209 test_init();
210 printk("Test string:%s\n", TEST_MSG);
211
212 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level,
213 NULL, 0, TEST_MSG);
214 zassert_equal(mode, EXP_MODE(ZERO_COPY));
215
216 Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level,
217 NULL, 0, TEST_MSG);
218 zassert_equal(mode, EXP_MODE(FROM_STACK));
219
220 z_log_msg_runtime_create(domain, source,
221 level, NULL, 0, 0, TEST_MSG);
222
223 validate_base_message_set(source, domain, level,
224 TEST_TIMESTAMP_INIT_VALUE,
225 NULL, 0, TEST_MSG);
226 }
227
ZTEST(log_msg,test_log_msg_various_args)228 ZTEST(log_msg, test_log_msg_various_args)
229 {
230 #undef TEST_MSG
231 #define TEST_MSG "%d %d %lld %p %lld %p"
232 static const uint8_t domain = 3;
233 static const uint8_t level = 2;
234 const void *source = (const void *)123;
235 int mode;
236 uint8_t u = 0x45;
237 signed char s8 = -5;
238 long long lld = 0x12341234563412;
239 char str[256];
240 static const int iarray[] = {1, 2, 3, 4};
241
242 test_init();
243 printk("Test string:%s\n", TEST_MSG);
244
245 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0,
246 TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray);
247 zassert_equal(mode, EXP_MODE(ZERO_COPY));
248
249 Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0,
250 TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray);
251 zassert_equal(mode, EXP_MODE(FROM_STACK));
252
253 z_log_msg_runtime_create(domain, (void *)source, level, NULL,
254 0, 0, TEST_MSG, s8, u, lld, str, lld, iarray);
255 snprintfcb(str, sizeof(str), TEST_MSG, s8, u, lld, str, lld, iarray);
256
257 validate_base_message_set(source, domain, level,
258 TEST_TIMESTAMP_INIT_VALUE,
259 NULL, 0, str);
260 }
261
ZTEST(log_msg,test_log_msg_only_data)262 ZTEST(log_msg, test_log_msg_only_data)
263 {
264 static const uint8_t domain = 3;
265 static const uint8_t level = 2;
266 const void *source = (const void *)123;
267 int mode;
268 static const uint8_t array[] = {1, 2, 3, 4};
269
270 test_init();
271
272 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, array,
273 sizeof(array));
274 zassert_equal(mode, EXP_MODE(FROM_STACK));
275
276 Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, array,
277 sizeof(array));
278 zassert_equal(mode, EXP_MODE(FROM_STACK));
279
280 z_log_msg_runtime_create(domain, (void *)source, level, array,
281 sizeof(array), 0, NULL);
282
283 validate_base_message_set(source, domain, level,
284 TEST_TIMESTAMP_INIT_VALUE,
285 array, sizeof(array), NULL);
286 }
287
ZTEST(log_msg,test_log_msg_string_and_data)288 ZTEST(log_msg, test_log_msg_string_and_data)
289 {
290 #undef TEST_MSG
291 #define TEST_MSG "test"
292
293 static const uint8_t domain = 3;
294 static const uint8_t level = 2;
295 const void *source = (const void *)123;
296 int mode;
297 static const uint8_t array[] = {1, 2, 3, 4};
298
299 test_init();
300
301 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, array,
302 sizeof(array), TEST_MSG);
303 zassert_equal(mode, EXP_MODE(FROM_STACK));
304
305 Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, array,
306 sizeof(array), TEST_MSG);
307 zassert_equal(mode, EXP_MODE(FROM_STACK));
308
309 z_log_msg_runtime_create(domain, (void *)source, level, array,
310 sizeof(array), 0, TEST_MSG);
311
312 validate_base_message_set(source, domain, level,
313 TEST_TIMESTAMP_INIT_VALUE,
314 array, sizeof(array), TEST_MSG);
315 }
316
ZTEST(log_msg,test_log_msg_fp)317 ZTEST(log_msg, test_log_msg_fp)
318 {
319 if (!(IS_ENABLED(CONFIG_CBPRINTF_FP_SUPPORT) && IS_ENABLED(CONFIG_FPU))) {
320 return;
321 }
322
323 #undef TEST_MSG
324 #define TEST_MSG "%d %lld %f %p %f %p"
325
326 static const uint8_t domain = 3;
327 static const uint8_t level = 2;
328 const void *source = (const void *)123;
329 int mode;
330 long long lli = 0x1122334455;
331 float f = 1.234f;
332 double d = 11.3434;
333 char str[256];
334 int i = -100;
335
336 test_init();
337
338 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0,
339 TEST_MSG, i, lli, (double)f, &i, d, source);
340 zassert_equal(mode, EXP_MODE(ZERO_COPY));
341
342 Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0,
343 TEST_MSG, i, lli, (double)f, &i, d, source);
344 zassert_equal(mode, EXP_MODE(FROM_STACK));
345
346 z_log_msg_runtime_create(domain, (void *)source, level, NULL, 0, 0,
347 TEST_MSG, i, lli, (double)f, &i, d, source);
348 snprintfcb(str, sizeof(str), TEST_MSG, i, lli, (double)f, &i, d, source);
349
350 validate_base_message_set(source, domain, level,
351 TEST_TIMESTAMP_INIT_VALUE,
352 NULL, 0, str);
353 }
354
get_msg_validate_length(uint32_t exp_len)355 static void get_msg_validate_length(uint32_t exp_len)
356 {
357 uint32_t len;
358 union log_msg_generic *msg;
359
360 msg = z_log_msg_claim(NULL);
361 len = log_msg_generic_get_wlen((union mpsc_pbuf_generic *)msg);
362
363 zassert_equal(len, exp_len, "Unexpected message length %d (exp:%d)",
364 len, exp_len);
365
366 z_log_msg_free(msg);
367 }
368
ZTEST(log_msg,test_mode_size_plain_string)369 ZTEST(log_msg, test_mode_size_plain_string)
370 {
371 static const uint8_t domain = 3;
372 static const uint8_t level = 2;
373 const void *source = (const void *)123;
374 uint32_t exp_len;
375 int mode;
376
377 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level, NULL, 0,
378 "test str");
379 zassert_equal(mode, EXP_MODE(ZERO_COPY),
380 "Unexpected creation mode");
381
382 Z_LOG_MSG_CREATE3(0, mode, 0, domain, source, level, NULL, 0,
383 "test str");
384 zassert_equal(mode, EXP_MODE(FROM_STACK),
385 "Unexpected creation mode");
386
387 /* Calculate expected message length. Message consists of:
388 * - header
389 * - package of plain string header + string pointer
390 *
391 * Message size is rounded up to the required alignment.
392 */
393 exp_len = offsetof(struct log_msg, data) +
394 /* package */sizeof(struct cbprintf_package_hdr_ext);
395
396 exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int);
397 get_msg_validate_length(exp_len);
398 get_msg_validate_length(exp_len);
399 }
400
ZTEST(log_msg,test_mode_size_data_only)401 ZTEST(log_msg, test_mode_size_data_only)
402 {
403 static const uint8_t domain = 3;
404 static const uint8_t level = 2;
405 const void *source = (const void *)123;
406 uint32_t exp_len;
407 int mode;
408 /* If data is present then message is created from stack, even though
409 * _from_stack is 0.
410 */
411 uint8_t data[] = {1, 2, 3};
412
413 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level,
414 data, sizeof(data));
415 zassert_equal(mode, EXP_MODE(FROM_STACK),
416 "Unexpected creation mode");
417
418 /* Calculate expected message length. Message consists of:
419 * - header
420 * - data
421 *
422 * Message size is rounded up to the required alignment.
423 */
424 exp_len = offsetof(struct log_msg, data) + sizeof(data);
425 exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int);
426 get_msg_validate_length(exp_len);
427 }
428
ZTEST(log_msg,test_mode_size_plain_str_data)429 ZTEST(log_msg, test_mode_size_plain_str_data)
430 {
431 static const uint8_t domain = 3;
432 static const uint8_t level = 2;
433 const void *source = (const void *)123;
434 uint32_t exp_len;
435 int mode;
436 /* If data is present then message is created from stack, even though
437 * _from_stack is 0.
438 */
439 uint8_t data[] = {1, 2, 3};
440
441 Z_LOG_MSG_CREATE3(1, mode, 0, domain, source, level,
442 data, sizeof(data), "test");
443 zassert_equal(mode, EXP_MODE(FROM_STACK),
444 "Unexpected creation mode");
445
446 /* Calculate expected message length. Message consists of:
447 * - header
448 * - data
449 *
450 * Message size is rounded up to the required alignment.
451 */
452 exp_len = offsetof(struct log_msg, data) + sizeof(data) +
453 /* package */sizeof(struct cbprintf_package_hdr_ext);
454 exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int);
455 get_msg_validate_length(exp_len);
456 }
457
ZTEST(log_msg,test_mode_size_str_with_strings)458 ZTEST(log_msg, test_mode_size_str_with_strings)
459 {
460 static const uint8_t domain = 3;
461 static const uint8_t level = 2;
462 const void *source = (const void *)123;
463 uint32_t exp_len;
464 int mode;
465 static const char *prefix = "prefix";
466
467 Z_LOG_MSG_CREATE3(1, mode,
468 1 /* accept one string pointer*/,
469 domain, source, level,
470 NULL, 0, "test %s", prefix);
471 zassert_equal(mode, EXP_MODE(ZERO_COPY),
472 "Unexpected creation mode");
473 Z_LOG_MSG_CREATE3(0, mode,
474 1 /* accept one string pointer*/,
475 domain, source, level,
476 NULL, 0, "test %s", prefix);
477 zassert_equal(mode, EXP_MODE(FROM_STACK),
478 "Unexpected creation mode");
479
480 /* Calculate expected message length. Message consists of:
481 * - header
482 * - package: header + fmt pointer + pointer
483 *
484 * Message size is rounded up to the required alignment.
485 */
486 exp_len = offsetof(struct log_msg, data) +
487 /* package */sizeof(struct cbprintf_package_hdr_ext) +
488 sizeof(const char *);
489 exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int);
490
491 get_msg_validate_length(exp_len);
492 get_msg_validate_length(exp_len);
493 }
494
ZTEST(log_msg,test_mode_size_str_with_2strings)495 ZTEST(log_msg, test_mode_size_str_with_2strings)
496 {
497 #undef TEST_STR
498 #define TEST_STR "%s test %s"
499
500 static const uint8_t domain = 3;
501 static const uint8_t level = 2;
502 const void *source = (const void *)123;
503 uint32_t exp_len;
504 int mode;
505 static const char *prefix = "prefix";
506 char sufix[] = "sufix";
507
508 Z_LOG_MSG_CREATE3(1, mode,
509 1 /* accept one string pointer*/,
510 domain, source, level,
511 NULL, 0, TEST_STR, prefix, sufix);
512 zassert_equal(mode, EXP_MODE(FROM_STACK),
513 "Unexpected creation mode");
514 Z_LOG_MSG_CREATE3(0, mode,
515 1 /* accept one string pointer*/,
516 domain, source, level,
517 NULL, 0, TEST_STR, prefix, sufix);
518 zassert_equal(mode, EXP_MODE(FROM_STACK),
519 "Unexpected creation mode");
520
521 /* Calculate expected message length. Message consists of:
522 * - header
523 * - package: header + fmt pointer + 2 pointers
524 * - index location of read only string
525 *
526 * Message size is rounded up to the required alignment.
527 */
528 exp_len = offsetof(struct log_msg, data) +
529 /* package */sizeof(struct cbprintf_package_hdr_ext) +
530 2 * sizeof(const char *) + 2 + strlen(sufix);
531
532 exp_len = ROUND_UP(exp_len, Z_LOG_MSG_ALIGNMENT) / sizeof(int);
533
534 get_msg_validate_length(exp_len);
535 get_msg_validate_length(exp_len);
536 }
537
timestamp_get_inc(void)538 static log_timestamp_t timestamp_get_inc(void)
539 {
540 return timestamp++;
541 }
542
ZTEST(log_msg,test_saturate)543 ZTEST(log_msg, test_saturate)
544 {
545 if (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
546 return;
547 }
548
549 uint32_t exp_len =
550 ROUND_UP(offsetof(struct log_msg, data) + 2 * sizeof(void *),
551 Z_LOG_MSG_ALIGNMENT);
552 uint32_t exp_capacity = CONFIG_LOG_BUFFER_SIZE / exp_len;
553 int mode;
554 union log_msg_generic *msg;
555
556 test_init();
557 timestamp = 0;
558 log_set_timestamp_func(timestamp_get_inc, 0);
559
560 for (int i = 0; i < exp_capacity; i++) {
561 Z_LOG_MSG_CREATE3(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
562 }
563
564 zassert_equal(z_log_dropped_read_and_clear(), 0, "No dropped messages.");
565
566 /* Message should not fit in and be dropped. */
567 Z_LOG_MSG_CREATE3(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
568 Z_LOG_MSG_CREATE3(0, mode, 0, 0, (void *)1, 2, NULL, 0, "test");
569 z_log_msg_runtime_create(0, (void *)1, 2, NULL, 0, 0, "test");
570
571 zassert_equal(z_log_dropped_read_and_clear(), 3, "No dropped messages.");
572
573 for (int i = 0; i < exp_capacity; i++) {
574 msg = z_log_msg_claim(NULL);
575 zassert_equal(log_msg_get_timestamp(&msg->log), i,
576 "Unexpected timestamp used for message id");
577 z_log_msg_free(msg);
578 }
579
580 msg = z_log_msg_claim(NULL);
581
582 zassert_equal(msg, NULL, "Expected no pending messages");
583 }
584
585 /*test case main entry*/
586 ZTEST_SUITE(log_msg, NULL, NULL, NULL, NULL, NULL);
587
