1 /*
2 * Copyright (c) 2022 Nordic Semiconductor ASA
3 * Copyright (c) 2023 Meta
4 *
5 * SPDX-License-Identifier: Apache-2.0
6 */
7
8 #include <stdbool.h>
9 #include <stdint.h>
10 #include <string.h>
11
12 #include <zephyr/kernel.h>
13 #include <zephyr/logging/log.h>
14 #include <zephyr/logging/log_ctrl.h>
15 #include <zephyr/logging/log_backend.h>
16 #include <zephyr/random/random.h>
17 #include <zephyr/sys/util.h>
18 #include <zephyr/ztest.h>
19
20 /* maximum time to wait before aborting thread in case of 0 log messages / second */
21 #define MAX_STALL_TIMEOUT_S 3
22 /* maximum time (seconds) to wait for logging thread to finish */
23 #define MAX_JOIN_TIMEOUT_S 1
24
25 #define WILL_STALL (CONFIG_TEST_INPUT_LOG_RATE == 0 || CONFIG_TEST_OUTPUT_LOG_RATE == 0)
26
27 #define MODULE_NAME test
28
29 LOG_MODULE_REGISTER(MODULE_NAME);
30
31 struct mock_log_backend {
32 uint32_t dropped;
33 uint32_t handled;
34 };
35
36 static uint32_t end_ms;
37 static uint32_t start_ms;
38 static uint32_t test_source_id;
39 static struct mock_log_backend mock_backend;
40
then(void)41 static inline uint32_t then(void)
42 {
43 return start_ms;
44 }
45
now(void)46 static inline uint32_t now(void)
47 {
48 /* some platforms currently _not_ starting uptime at 0!! */
49 return k_uptime_get_32();
50 }
51
end(void)52 static inline uint32_t end(void)
53 {
54 return end_ms;
55 }
56
create_start_end(void)57 static inline void create_start_end(void)
58 {
59 start_ms = k_uptime_get_32();
60 end_ms = start_ms;
61 /* some "fuzz" in ms to account for odd variances */
62 end_ms += MAX_STALL_TIMEOUT_S * MSEC_PER_SEC;
63
64 #if WILL_STALL
65 end_ms += MAX_STALL_TIMEOUT_S * MSEC_PER_SEC;
66 #elif CONFIG_TEST_INPUT_LOG_RATE > 0 && CONFIG_TEST_INPUT_LOG_RATE <= CONFIG_TEST_OUTPUT_LOG_RATE
67 end_ms += MSEC_PER_SEC * DIV_ROUND_UP(CONFIG_TEST_NUM_LOGS, CONFIG_TEST_INPUT_LOG_RATE);
68 #elif CONFIG_TEST_OUTPUT_LOG_RATE > 0 && CONFIG_TEST_INPUT_LOG_RATE > CONFIG_TEST_OUTPUT_LOG_RATE
69 end_ms += MSEC_PER_SEC * DIV_ROUND_UP(CONFIG_TEST_NUM_LOGS, CONFIG_TEST_OUTPUT_LOG_RATE);
70 #else
71 #error "Impossible scenario"
72 #endif
73
74 TC_PRINT("Start time: %u ms\n", start_ms);
75 TC_PRINT("End time: %u ms\n", end_ms);
76 }
77
handle_output(uint32_t i)78 static void handle_output(uint32_t i)
79 {
80 while (true) {
81 if (i + 1 <= (CONFIG_TEST_OUTPUT_LOG_RATE * (now() - then())) / MSEC_PER_SEC) {
82 break;
83 }
84 k_msleep(1);
85 }
86
87 ++mock_backend.handled;
88 }
89
handle_input(void)90 static void handle_input(void)
91 {
92 for (int i = 0; i < CONFIG_TEST_NUM_LOGS; i++) {
93 while (true) {
94 if (i + 1 <= CONFIG_TEST_INPUT_LOG_RATE * (now() - then()) / MSEC_PER_SEC) {
95 break;
96 }
97 zassert_true(now() <= end());
98 k_msleep(1);
99 }
100
101 LOG_INF("%u", i);
102 }
103 }
104
process(const struct log_backend * const backend,union log_msg_generic * msg)105 static void process(const struct log_backend *const backend, union log_msg_generic *msg)
106 {
107 size_t len;
108 uint8_t *package = log_msg_get_package(&msg->log, &len);
109
110 package += 2 * sizeof(void *);
111
112 handle_output(*(uint32_t *)package);
113 }
114
mock_init(struct log_backend const * const backend)115 static void mock_init(struct log_backend const *const backend)
116 {
117 }
118
panic(struct log_backend const * const backend)119 static void panic(struct log_backend const *const backend)
120 {
121 #if WILL_STALL
122 /* Don't panic! */
123 return;
124 #endif
125
126 zassert_true(false);
127 }
128
dropped(const struct log_backend * const backend,uint32_t cnt)129 static void dropped(const struct log_backend *const backend, uint32_t cnt)
130 {
131 mock_backend.dropped += cnt;
132 }
133
134 static const struct log_backend_api log_blocking_api = {
135 .process = process,
136 .panic = panic,
137 .init = mock_init,
138 .dropped = dropped,
139 };
140
141 LOG_BACKEND_DEFINE(blocking_log_backend, log_blocking_api, true, NULL);
142
143 BUILD_ASSERT(CONFIG_TEST_INPUT_LOG_RATE >= 0);
144 BUILD_ASSERT(CONFIG_TEST_OUTPUT_LOG_RATE >= 0);
145
print_input(void)146 static void print_input(void)
147 {
148 TC_PRINT("CONFIG_TEST_NUM_LOGS: %d\n", CONFIG_TEST_NUM_LOGS);
149 TC_PRINT("CONFIG_TEST_INPUT_LOG_RATE: %d\n", CONFIG_TEST_INPUT_LOG_RATE);
150 TC_PRINT("CONFIG_TEST_OUTPUT_LOG_RATE: %d\n", CONFIG_TEST_OUTPUT_LOG_RATE);
151 }
152
print_output(void)153 static void print_output(void)
154 {
155 TC_PRINT("Log backend dropped %u messages\n", mock_backend.dropped);
156 TC_PRINT("Log backend handled %u messages\n", mock_backend.handled);
157 }
158
test_blocking_thread_entry(void * p1,void * p2,void * p3)159 static void test_blocking_thread_entry(void *p1, void *p2, void *p3)
160 {
161 ARG_UNUSED(p1);
162 ARG_UNUSED(p2);
163 ARG_UNUSED(p3);
164
165 handle_input();
166 }
167 K_THREAD_DEFINE(test_blocking_thread, 4096, test_blocking_thread_entry, NULL, NULL, NULL,
168 K_HIGHEST_THREAD_PRIO, 0, UINT32_MAX);
169
170 #if WILL_STALL
171 ZTEST_EXPECT_FAIL(log_blocking, test_blocking);
172 #endif
ZTEST(log_blocking,test_blocking)173 ZTEST(log_blocking, test_blocking)
174 {
175 #if WILL_STALL
176 /*
177 * This is a workaround for a possible bug in the testing subsys:
178 * - comment-out ztest_test_fail() below
179 * - run with:
180 * west build -p auto -b qemu_riscv64 -t run \
181 * -T tests/subsys/logging/log_blocking/logging.blocking.rate.stalled
182 * - observe "Assertion failed at..."
183 * - technically, testsuite should pass. Since ZTEST_EXPECT_FAIL() is set. Never gets there.
184 * - run with:
185 * twister -i -p qemu_riscv64 -T tests/subsys/logging/log_blocking/
186 * - observe "..FAILED : Timeout"
187 * - possible conclusions:
188 * - test thread has not properly longjumped?
189 * - twister not detecting assertion failures?
190 * - twister expecting some other string and never sees it?
191 */
192 ztest_test_fail();
193 #endif
194
195 create_start_end();
196 k_thread_start(test_blocking_thread);
197 k_msleep(end() - now());
198
199 #if WILL_STALL
200 k_thread_abort(test_blocking_thread);
201 #endif
202 zassert_ok(k_thread_join(test_blocking_thread, K_SECONDS(MAX_JOIN_TIMEOUT_S)));
203
204 print_output();
205
206 zassert_equal(mock_backend.dropped, 0, "dropped %u / %u logs", mock_backend.dropped,
207 CONFIG_TEST_NUM_LOGS);
208
209 zassert_equal(mock_backend.handled, CONFIG_TEST_NUM_LOGS, "handled %u / %u logs",
210 mock_backend.handled, CONFIG_TEST_NUM_LOGS);
211 }
212
setup(void)213 static void *setup(void)
214 {
215 /*
216 * This testsuite was added mainly to address a regression caused
217 * by this subtle, but very different interpretation.
218 */
219 __ASSERT(K_TIMEOUT_EQ(K_NO_WAIT, K_MSEC(-1)), "K_NO_WAIT should be equal to K_MSEC(-1)");
220 __ASSERT(!K_TIMEOUT_EQ(K_FOREVER, K_MSEC(-1)),
221 "K_FOREVER should not be equal to K_MSEC(-1)");
222
223 test_source_id = log_source_id_get(STRINGIFY(MODULE_NAME));
224
225 print_input();
226
227 return NULL;
228 }
229
before(void * arg)230 static void before(void *arg)
231 {
232 memset(&mock_backend, 0, sizeof(mock_backend));
233 }
234
teardown(void * data)235 static void teardown(void *data)
236 {
237 ARG_UNUSED(data);
238 log_backend_disable(&blocking_log_backend);
239 }
240
241 ZTEST_SUITE(log_blocking, NULL, setup, before, NULL, teardown);
242
