1 /*
2 * Copyright (c) 2020 Intel Corporation
3 *
4 * SPDX-License-Identifier: Apache-2.0
5 */
6
7 /**
8 * @file
9 * @brief Additional test case for log core
10 *
11 */
12
13 #include <zephyr/tc_util.h>
14 #include <stdbool.h>
15 #include <zephyr/kernel.h>
16 #include <zephyr/ztest.h>
17 #include <zephyr/logging/log_backend.h>
18 #include <zephyr/logging/log_backend_std.h>
19 #include <zephyr/logging/log_ctrl.h>
20 #include <zephyr/logging/log.h>
21 #include <zephyr/logging/log_output.h>
22 #include <zephyr/sys/iterable_sections.h>
23
24 #define TEST_MESSAGE "test msg"
25
26 #define LOG_MODULE_NAME log_test
27 LOG_MODULE_REGISTER(LOG_MODULE_NAME, LOG_LEVEL_INF);
28 static K_SEM_DEFINE(log_sem, 0, 1);
29
30 #define TIMESTAMP_FREC (2000000)
31 ZTEST_BMEM uint32_t source_id;
32 /* used when log_msg create in user space */
33 ZTEST_BMEM uint8_t domain, level;
34 ZTEST_DMEM uint32_t msg_data = 0x1234;
35
36 static uint8_t buf;
char_out(uint8_t * data,size_t length,void * ctx)37 static int char_out(uint8_t *data, size_t length, void *ctx)
38 {
39 ARG_UNUSED(data);
40 ARG_UNUSED(ctx);
41 return length;
42 }
43 LOG_OUTPUT_DEFINE(log_output, char_out, &buf, 1);
44
45 struct backend_cb {
46 /* count log messages handled by this backend */
47 size_t counter;
48 /* count log messages handled immediately by this backend */
49 size_t sync;
50 /* inform put() to check timestamp of message against exp_timestamps */
51 bool check_timestamp;
52 uint32_t exp_timestamps[16];
53 /* inform put() to check severity of message against exp_severity */
54 bool check_severity;
55 uint16_t exp_severity[4];
56 /* inform put() to check domain_id of message */
57 bool check_domain_id;
58 /* How many messages have been logged.
59 * used in async mode, to make sure all logs have been handled by compare
60 * counter with total_logs
61 */
62 size_t total_logs;
63 };
64
process(const struct log_backend * const backend,union log_msg_generic * msg)65 static void process(const struct log_backend *const backend,
66 union log_msg_generic *msg)
67 {
68 uint32_t flags;
69 struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx;
70
71 /* If printk message skip it. */
72 if (log_msg_get_level(&(msg->log)) == LOG_LEVEL_INTERNAL_RAW_STRING) {
73 return;
74 }
75
76 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
77 cb->sync++;
78 }
79
80 if (cb->check_domain_id) {
81 zassert_equal(log_msg_get_domain(&(msg->log)), Z_LOG_LOCAL_DOMAIN_ID,
82 "Unexpected domain id");
83 }
84
85 if (cb->check_timestamp) {
86 uint32_t exp_timestamp = cb->exp_timestamps[cb->counter];
87
88 zassert_equal(log_msg_get_timestamp(&(msg->log)), exp_timestamp,
89 "Unexpected message index");
90 }
91
92 if (cb->check_severity) {
93 zassert_equal(log_msg_get_level(&(msg->log)),
94 cb->exp_severity[cb->counter],
95 "Unexpected log severity");
96 }
97
98 cb->counter++;
99 if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
100 if (cb->counter == cb->total_logs) {
101 k_sem_give(&log_sem);
102 }
103 }
104
105 if (k_is_user_context()) {
106 zassert_equal(log_msg_get_domain(&(msg->log)), domain,
107 "Unexpected domain id");
108
109 zassert_equal(log_msg_get_level(&(msg->log)), level,
110 "Unexpected log severity");
111 }
112
113 flags = log_backend_std_get_flags();
114 log_output_msg_process(&log_output, &msg->log, flags);
115 }
116
panic(const struct log_backend * const backend)117 static void panic(const struct log_backend *const backend)
118 {
119 ARG_UNUSED(backend);
120 }
121
122 const struct log_backend_api log_backend_test_api = {
123 .process = process,
124 .panic = panic,
125 };
126
127 LOG_BACKEND_DEFINE(backend1, log_backend_test_api, false);
128 struct backend_cb backend1_cb;
129
130 LOG_BACKEND_DEFINE(backend2, log_backend_test_api, false);
131 struct backend_cb backend2_cb;
132
133 /* The logging system support user customize timestamping in log messages
134 * by register a timestamp function, in timestamp_get() below, just return
135 * a counter as timestamp for different messages.
136 * when install this timestamp function, timestamping frequency is set to
137 * 2000000, means 2 timestamp/us
138 */
139 #ifndef CONFIG_USERSPACE
140 static uint32_t stamp;
timestamp_get(void)141 static uint32_t timestamp_get(void)
142 {
143 stamp++;
144 return log_output_timestamp_to_us(stamp * 2);
145 }
146
log_setup(bool backend2_enable)147 static void log_setup(bool backend2_enable)
148 {
149 stamp = 0U;
150
151 log_init();
152 #ifndef CONFIG_LOG_PROCESS_THREAD
153 log_thread_set(k_current_get());
154 #endif
155
156 memset(&backend1_cb, 0, sizeof(backend1_cb));
157
158 log_backend_enable(&backend1, &backend1_cb, LOG_LEVEL_DBG);
159
160 if (backend2_enable) {
161 memset(&backend2_cb, 0, sizeof(backend2_cb));
162
163 log_backend_enable(&backend2, &backend2_cb, LOG_LEVEL_DBG);
164 } else {
165 log_backend_disable(&backend2);
166 }
167 }
168
169 #endif
170
log_test_process(void)171 static bool log_test_process(void)
172 {
173 if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
174 /* waiting for all logs have been handled */
175 k_sem_take(&log_sem, K_FOREVER);
176 return false;
177 } else {
178 return log_process();
179 }
180 }
181
182 /**
183 * @brief Support multi-processor systems
184 *
185 * @details Logging system identify domain/processor by domain_id which is now
186 * statically configured by Z_LOG_LOCAL_DOMAIN_ID
187 *
188 * @addtogroup logging
189 */
190
191 #ifndef CONFIG_USERSPACE
192
193 /**
194 * @brief Create Tests for Dynamic Loadable Logging Backends
195 *
196 * @details Test the three APIs, log_backend_activate, log_backend_is_active and
197 * log_backend_deactivate.
198 *
199 * @addtogroup logging
200 */
ZTEST(test_log_core_additional,test_log_backend)201 ZTEST(test_log_core_additional, test_log_backend)
202 {
203 log_init();
204
205 zassert_false(log_backend_is_active(&backend1));
206 log_backend_activate(&backend1, NULL);
207 zassert_true(log_backend_is_active(&backend1));
208 log_backend_deactivate(&backend1);
209 zassert_false(log_backend_is_active(&backend1));
210 }
211
ZTEST(test_log_core_additional,test_log_domain_id)212 ZTEST(test_log_core_additional, test_log_domain_id)
213 {
214 log_setup(false);
215
216 backend1_cb.check_domain_id = true;
217 backend1_cb.total_logs = 1;
218
219 LOG_INF("info message for domain id test");
220
221 while (log_test_process()) {
222 }
223
224 zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
225 "Unexpected amount of messages received by the backend");
226 }
227
228 /**
229 * @brief Synchronous processing of logging messages.
230 *
231 * @details if CONFIG_LOG_MODE_IMMEDIATE is enabled, log message is
232 * handled immediately
233 *
234 * @addtogroup logging
235 */
ZTEST(test_log_core_additional,test_log_sync)236 ZTEST(test_log_core_additional, test_log_sync)
237 {
238 TC_PRINT("Logging synchronously\n");
239
240 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
241 log_setup(false);
242 LOG_INF("Log immediately");
243 LOG_INF("Log immediately");
244
245 /* log immediately, no log_process needed */
246 zassert_equal(2, backend1_cb.sync,
247 "Unexpected amount of messages received by the backend.");
248 } else {
249 ztest_test_skip();
250 }
251 }
252
253 /**
254 * @brief Early logging
255 * @details Handle log message attempts as well as creating new log contexts
256 * instance, before the backend are active
257 *
258 * @addtogroup logging
259 */
ZTEST(test_log_core_additional,test_log_early_logging)260 ZTEST(test_log_core_additional, test_log_early_logging)
261 {
262 if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
263 ztest_test_skip();
264 } else {
265 log_init();
266
267 /* deactivate other backends */
268 STRUCT_SECTION_FOREACH(log_backend, backend) {
269 if (strcmp(backend->name, "test")) {
270 log_backend_deactivate(backend);
271 }
272 }
273
274 TC_PRINT("Create log message before backend active\n");
275
276 LOG_INF("log info before backend active");
277 LOG_WRN("log warn before backend active");
278 LOG_ERR("log error before backend active");
279
280 TC_PRINT("Activate backend with context");
281 memset(&backend1_cb, 0, sizeof(backend1_cb));
282 backend1_cb.total_logs = 3;
283 log_backend_enable(&backend1, &backend1_cb, LOG_LEVEL_DBG);
284
285 while (log_test_process()) {
286 }
287
288 zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
289 "Unexpected amount of messages received. %d",
290 backend1_cb.counter);
291 }
292 }
293
294 /**
295 * @brief Log severity
296 *
297 * @details This module is registered with LOG_LEVEL_INF, LOG_LEVEL_DBG will be
298 * filtered out at compile time, only 3 message handled
299 *
300 * @addtogroup logging
301 */
ZTEST(test_log_core_additional,test_log_severity)302 ZTEST(test_log_core_additional, test_log_severity)
303 {
304 log_setup(false);
305
306 backend1_cb.check_severity = true;
307 backend1_cb.exp_severity[0] = LOG_LEVEL_INF;
308 backend1_cb.exp_severity[1] = LOG_LEVEL_WRN;
309 backend1_cb.exp_severity[2] = LOG_LEVEL_ERR;
310
311 LOG_INF("info message");
312 LOG_WRN("warning message");
313 LOG_ERR("error message");
314 backend1_cb.total_logs = 3;
315
316 while (log_test_process()) {
317 }
318
319 zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
320 "Unexpected amount of messages received by the backend.");
321 }
322
323 /**
324 * @brief Customizable timestamping in log messages
325 *
326 * @details Log core permit user to register customized timestamp function
327 *
328 * @addtogroup logging
329 */
ZTEST(test_log_core_additional,test_log_timestamping)330 ZTEST(test_log_core_additional, test_log_timestamping)
331 {
332 stamp = 0U;
333
334 log_init();
335 /* deactivate all other backend */
336 STRUCT_SECTION_FOREACH(log_backend, backend) {
337 if ((backend == &backend1) || (backend == &backend2)) {
338 log_backend_deactivate(backend);
339 }
340 }
341
342 TC_PRINT("Register timestamp function\n");
343 zassert_equal(-EINVAL, log_set_timestamp_func(NULL, 0),
344 "Expects successful timestamp function setting.");
345 zassert_equal(0, log_set_timestamp_func(timestamp_get, TIMESTAMP_FREC),
346 "Expects successful timestamp function setting.");
347
348 memset(&backend1_cb, 0, sizeof(backend1_cb));
349 log_backend_enable(&backend1, &backend1_cb, LOG_LEVEL_DBG);
350
351 backend1_cb.check_timestamp = true;
352
353 backend1_cb.exp_timestamps[0] = 1U;
354 backend1_cb.exp_timestamps[1] = 2U;
355 backend1_cb.exp_timestamps[2] = 3U;
356
357 LOG_INF("test timestamp");
358 LOG_INF("test timestamp");
359 LOG_WRN("test timestamp");
360 backend1_cb.total_logs = 3;
361
362 while (log_test_process()) {
363 }
364
365 zassert_equal(backend1_cb.total_logs,
366 backend1_cb.counter,
367 "Unexpected amount of messages received by the backend.");
368 }
369
370 /**
371 * @brief Multiple logging backends
372 *
373 * @details Enable two backends in this module and enable UART backend
374 * by CONFIG_LOG_BACKEND_UART, there are three backends at least.
375 *
376 * @addtogroup logging
377 */
378
379 #define UART_BACKEND "log_backend_uart"
ZTEST(test_log_core_additional,test_multiple_backends)380 ZTEST(test_log_core_additional, test_multiple_backends)
381 {
382 int cnt;
383
384 TC_PRINT("Test multiple backends");
385 /* enable both backend1 and backend2 */
386 log_setup(true);
387 STRUCT_SECTION_COUNT(log_backend, &cnt);
388 zassert_true((cnt >= 2),
389 "There is no multi backends");
390
391 if (IS_ENABLED(CONFIG_LOG_BACKEND_UART)) {
392 bool have_uart = false;
393
394 STRUCT_SECTION_FOREACH(log_backend, backend) {
395 if (strcmp(backend->name, UART_BACKEND) == 0) {
396 have_uart = true;
397 }
398 }
399 zassert_true(have_uart, "There is no UART log backend found");
400 }
401 }
402
403 /**
404 * @brief Process all logging activities using a dedicated thread
405 *
406 * @addtogroup logging
407 */
408
409 #ifdef CONFIG_LOG_PROCESS_THREAD
ZTEST(test_log_core_additional,test_log_thread)410 ZTEST(test_log_core_additional, test_log_thread)
411 {
412 TC_PRINT("Logging buffer is configured to %d bytes\n",
413 CONFIG_LOG_BUFFER_SIZE);
414
415 TC_PRINT("Stack size of logging thread is configured by ");
416 TC_PRINT("CONFIG_LOG_PROCESS_THREAD_STACK_SIZE: %d bytes\n",
417 CONFIG_LOG_PROCESS_THREAD_STACK_SIZE);
418
419 log_setup(false);
420
421 zassert_false(log_data_pending());
422
423 LOG_INF("log info to log thread");
424 LOG_WRN("log warning to log thread");
425 LOG_ERR("log error to log thread");
426
427 zassert_true(log_data_pending());
428
429 /* wait 2 seconds for logging thread to handle this log message*/
430 k_sleep(K_MSEC(2000));
431 zassert_equal(3, backend1_cb.counter,
432 "Unexpected amount of messages received by the backend.");
433 zassert_false(log_data_pending());
434 }
435 #else
ZTEST(test_log_core_additional,test_log_thread)436 ZTEST(test_log_core_additional, test_log_thread)
437 {
438 ztest_test_skip();
439 }
440 #endif
441
442 /**
443 * @brief Process all logging activities using a dedicated thread (trigger immediate processing)
444 *
445 * @addtogroup logging
446 */
447
448 #ifdef CONFIG_LOG_PROCESS_THREAD
ZTEST(test_log_core_additional,test_log_thread_trigger)449 ZTEST(test_log_core_additional, test_log_thread_trigger)
450 {
451 log_setup(false);
452
453 zassert_false(log_data_pending());
454
455 LOG_INF("log info to log thread");
456 LOG_WRN("log warning to log thread");
457 LOG_ERR("log error to log thread");
458
459 zassert_true(log_data_pending());
460
461 /* Trigger log thread to process messages as soon as possible. */
462 log_thread_trigger();
463
464 /* wait 1ms to give logging thread chance to handle these log messages. */
465 k_sleep(K_MSEC(1));
466 zassert_equal(3, backend1_cb.counter,
467 "Unexpected amount of messages received by the backend.");
468 zassert_false(log_data_pending());
469 }
470 #else
ZTEST(test_log_core_additional,test_log_thread_trigger)471 ZTEST(test_log_core_additional, test_log_thread_trigger)
472 {
473 ztest_test_skip();
474 }
475 #endif
476
call_log_generic(const char * fmt,...)477 static void call_log_generic(const char *fmt, ...)
478 {
479 va_list ap;
480
481 va_start(ap, fmt);
482 log_generic(LOG_LEVEL_INF, fmt, ap);
483 va_end(ap);
484 }
485
ZTEST(test_log_core_additional,test_log_generic)486 ZTEST(test_log_core_additional, test_log_generic)
487 {
488 char *log_msg = "log user space";
489 int i = 100;
490
491 log_setup(false);
492 backend1_cb.total_logs = 4;
493
494 call_log_generic("log generic");
495 call_log_generic("log generic: %s", log_msg);
496 call_log_generic("log generic %d\n", i);
497 call_log_generic("log generic %d, %d\n", i, 1);
498 while (log_test_process()) {
499 }
500 }
501
ZTEST(test_log_core_additional,test_log_msg_create)502 ZTEST(test_log_core_additional, test_log_msg_create)
503 {
504 log_setup(false);
505 if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
506 int mode;
507
508 domain = 3;
509 level = 2;
510
511 z_log_msg_runtime_create(domain, __log_current_const_data,
512 level, &msg_data, 0,
513 sizeof(msg_data), NULL);
514 /* try z_log_msg_static_create() */
515 Z_LOG_MSG_STACK_CREATE(0, domain, __log_current_const_data,
516 level, &msg_data,
517 sizeof(msg_data), NULL);
518
519 Z_LOG_MSG_CREATE(!IS_ENABLED(CONFIG_USERSPACE), mode,
520 Z_LOG_LOCAL_DOMAIN_ID, NULL,
521 LOG_LEVEL_INF, NULL, 0, TEST_MESSAGE);
522
523 backend1_cb.total_logs = 3;
524
525 while (log_test_process()) {
526 }
527 }
528 }
529
530 #else
531
ZTEST_USER(test_log_core_additional,test_log_msg_create_user)532 ZTEST_USER(test_log_core_additional, test_log_msg_create_user)
533 {
534 int mode;
535
536 domain = 3;
537 level = 2;
538
539 z_log_msg_runtime_create(domain, NULL,
540 level, &msg_data, 0,
541 sizeof(msg_data), TEST_MESSAGE);
542 /* try z_log_msg_static_create() */
543 Z_LOG_MSG_STACK_CREATE(0, domain, NULL,
544 level, &msg_data,
545 sizeof(msg_data), TEST_MESSAGE);
546
547 Z_LOG_MSG_CREATE(!IS_ENABLED(CONFIG_USERSPACE), mode,
548 Z_LOG_LOCAL_DOMAIN_ID, NULL,
549 LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, TEST_MESSAGE);
550
551 while (log_test_process()) {
552 }
553 }
554
555 #endif /** CONFIG_USERSPACE **/
556
557 /* The log process thread has the K_LOWEST_APPLICATION_THREAD_PRIO, adjust it
558 * to a higher priority to increase the chances of being scheduled to handle
559 * log message as soon as possible
560 */
promote_log_thread(const struct k_thread * thread,void * user_data)561 void promote_log_thread(const struct k_thread *thread, void *user_data)
562 {
563 if (!(strcmp(thread->name, "logging"))) {
564 k_thread_priority_set((k_tid_t)thread, -1);
565 }
566 }
567
test_log_core_additional_setup(void)568 static void *test_log_core_additional_setup(void)
569 {
570 #ifdef CONFIG_LOG_PROCESS_THREAD
571 k_thread_foreach(promote_log_thread, NULL);
572 #endif
573 return NULL;
574 }
575
576 ZTEST_SUITE(test_log_core_additional, NULL, test_log_core_additional_setup, NULL, NULL, NULL);
577
