1 /*
2 * Arm SCP/MCP Software
3 * Copyright (c) 2020-2022, Arm Limited and Contributors. All rights reserved.
4 *
5 * SPDX-License-Identifier: BSD-3-Clause
6 */
7
8 #include <fwk_assert.h>
9 #include <fwk_attributes.h>
10 #include <fwk_interrupt.h>
11 #include <fwk_log.h>
12 #include <fwk_ring.h>
13 #include <fwk_status.h>
14 #include <fwk_time.h>
15
16 #include <inttypes.h>
17 #include <limits.h>
18 #include <stdarg.h>
19 #include <stdbool.h>
20 #include <stddef.h>
21 #include <stdint.h>
22 #include <stdio.h>
23 #include <string.h>
24
25 static const char FWK_LOG_TERMINATOR[] = { '\n', '\0' };
26
27 static struct {
28 unsigned int dropped; /* Count of messages lost */
29
30 #ifdef FWK_LOG_BUFFERED
31 struct fwk_ring ring; /* Buffer for formatted messages */
32
33 unsigned char remaining; /* Remaining characters in the current message */
34 #endif
35 } fwk_log_ctx = { 0 };
36
37 static struct fwk_io_stream *fwk_log_stream;
38
39 #ifdef FWK_LOG_BUFFERED
fwk_log_stream_init(void)40 static FWK_CONSTRUCTOR void fwk_log_stream_init(void)
41 {
42 static char storage[FMW_LOG_BUFFER_SIZE];
43
44 fwk_ring_init(&fwk_log_ctx.ring, storage, sizeof(storage));
45 }
46 #endif
47
fwk_log_init(void)48 int fwk_log_init(void)
49 {
50 static struct fwk_io_stream stream;
51
52 int status = FWK_SUCCESS;
53
54 if (fwk_id_is_equal(FMW_LOG_DRAIN_ID, FMW_IO_STDOUT_ID)) {
55 fwk_log_stream = fwk_io_stdout;
56 } else if (!fwk_id_is_equal(FMW_LOG_DRAIN_ID, FWK_ID_NONE)) {
57 status = fwk_io_open(&stream, FMW_LOG_DRAIN_ID, FWK_IO_MODE_WRITE);
58 if (fwk_expect(status == FWK_SUCCESS)) {
59 fwk_log_stream = &stream;
60 }
61 }
62
63 return status;
64 }
65
66 #ifdef FWK_LOG_BUFFERED
fwk_log_buffer(struct fwk_ring * ring,const char * message)67 static bool fwk_log_buffer(struct fwk_ring *ring, const char *message)
68 {
69 unsigned char length = strlen(message) + 1; /* +1 for null terminator */
70
71 /*
72 * Log messages are stored in the ring buffer prefixed with their length
73 * (including the null terminator). Care must be taken to ensure the length
74 * of each message does not exceed `UCHAR_MAX`.
75 */
76
77 if ((sizeof(length) + length) > fwk_ring_get_free(ring)) {
78 return false; /* Not enough buffer space */
79 }
80
81 fwk_ring_push(ring, (char *)&length, sizeof(length));
82 fwk_ring_push(ring, message, length);
83
84 return true;
85 }
86 #endif
87
fwk_log_vsnprintf(size_t buffer_size,char buffer[buffer_size],const char * format,va_list * args)88 static void fwk_log_vsnprintf(
89 size_t buffer_size,
90 char buffer[buffer_size],
91 const char *format,
92 va_list *args)
93 {
94 fwk_timestamp_t timestamp = 0;
95 fwk_duration_ns_t duration = 0;
96
97 uint32_t duration_s = 0;
98 uint32_t duration_us = 0;
99
100 size_t length = 0;
101
102 char *newline;
103
104 buffer_size -= strlen(FWK_LOG_TERMINATOR);
105
106 /*
107 * We start by generating a timestamp for the message using the number of
108 * nanoseconds since boot.
109 */
110
111 timestamp = fwk_time_current();
112 duration = fwk_time_stamp_duration(timestamp);
113
114 /*
115 * Newlib support for printing 64-bit integers with `printf()` is
116 * optional and actually disabled by default in GNU Arm Embedded. To
117 * print the timestamp values under this configuration we need to
118 * truncate the timestamp values to 32 bits.
119 *
120 * This gives us a theoretical maximum of 136 years' worth of seconds on the
121 * timestamp, which is still plenty.
122 */
123
124 duration_s = (uint32_t)fwk_time_duration_s(duration);
125 duration_us = (uint32_t)fwk_time_duration_us(duration % FWK_S(1));
126
127 /* Generate the timestamp at the beginning of the buffer */
128 length = (size_t)snprintf(
129 buffer,
130 buffer_size,
131 "[%5" PRIu32 ".%06" PRIu32 "] ",
132 duration_s,
133 duration_us);
134 fwk_assert(length < buffer_size);
135
136 /*
137 * We then need to `snprintf()` the message into a temporary buffer because
138 * we need to manipulate it before we print or store it.
139 */
140
141 length += vsnprintf(buffer + length, buffer_size - length, format, *args);
142 length = FWK_MIN(length, buffer_size - 1);
143
144 /*
145 * Figure out if the user has included a newline, in which case we consider
146 * that to be the end of the message. This stops us from being able to
147 * create multi-line messages, but means we can properly generate timestamps
148 * on a line-by-line basis.
149 */
150
151 newline = strchr(buffer, (int)'\n');
152 if (newline == NULL) {
153 newline = buffer + length;
154 }
155
156 /*
157 * Lastly, we follow through on the termination with a proper carriage
158 * return and newline. Terminals that don't care about the carriage return
159 * will generally ignore it, but most terminals require it in order to start
160 * the next line at the first column.
161 */
162
163 (void)memcpy(newline, FWK_LOG_TERMINATOR, sizeof(FWK_LOG_TERMINATOR));
164 }
165
fwk_log_snprintf(size_t buffer_size,char buffer[buffer_size],const char * format,...)166 static void fwk_log_snprintf(
167 size_t buffer_size,
168 char buffer[buffer_size],
169 const char *format,
170 ...)
171 {
172 va_list args;
173
174 va_start(args, format);
175 fwk_log_vsnprintf(buffer_size, buffer, format, &args);
176 va_end(args);
177 }
178
fwk_log_banner(void)179 static bool fwk_log_banner(void)
180 {
181 #ifndef FMW_LOG_MINIMAL_BANNER
182 const char *banner =
183 " ___ ___ ___ __ _\n"
184 "/ __|/ __| _ \\___ / _(_)_ _ _ ____ __ ____ _ _ _ ___\n"
185 "\\__ | (__| _|___| _| | '_| ' \\ V V / _` | '_/ -_)\n"
186 "|___/\\___|_| |_| |_|_| |_|_|_\\_/\\_/\\__,_|_| \\___|\n"
187 "\n" BUILD_VERSION_DESCRIBE_STRING "\n";
188 #else
189 const char *banner = "SCP-firmware " BUILD_VERSION_DESCRIBE_STRING "\n";
190 #endif
191
192 while (banner != NULL) {
193 char buffer[FMW_LOG_COLUMNS + sizeof(FWK_LOG_TERMINATOR)];
194
195 fwk_log_snprintf(sizeof(buffer), buffer, "%s", banner);
196
197 if (fwk_io_puts(fwk_log_stream, buffer) != FWK_SUCCESS) {
198 return false;
199 }
200
201 banner = strchr(banner, (int)'\n');
202 if (banner != NULL) {
203 banner++;
204 }
205 }
206
207 return true;
208 }
209
fwk_log_printf(const char * format,...)210 void fwk_log_printf(const char *format, ...)
211 {
212 unsigned int flags;
213 static bool banner = false;
214
215 char buffer[FMW_LOG_COLUMNS + sizeof(FWK_LOG_TERMINATOR)];
216
217 va_list args;
218
219 flags = fwk_interrupt_global_disable(); /* Facilitate reentrancy */
220
221 /*
222 * We don't have any way for the log drain entity to communicate that it is
223 * ready to accept prints, so our best bet for printing the banner is just
224 * to keep trying to do it before every call to this function, until it
225 * succeeds.
226 */
227
228 if (!banner) {
229 banner = fwk_log_banner();
230 }
231
232 va_start(args, format);
233 fwk_log_vsnprintf(sizeof(buffer), buffer, format, &args);
234 va_end(args);
235
236 #ifdef FWK_LOG_BUFFERED
237 /*
238 * Buffer the message that we've received so that the scheduler can choose
239 * when we do the heavy-lifting (typically once we're in an idle state).
240 */
241
242 bool dropped = !fwk_log_buffer(&fwk_log_ctx.ring, buffer);
243 if (dropped) {
244 /*
245 * If we don't have enough room left in the buffer, then we're out of
246 * luck. We don't want to spend what are likely to be precious cycles
247 * printing on the always-on backend, so our best option is simply to
248 * mark the message as dropped and move on.
249 */
250
251 fwk_log_ctx.dropped++;
252 }
253 #else
254 int status = fwk_io_puts(fwk_log_stream, buffer);
255 if (status != FWK_SUCCESS) {
256 fwk_log_ctx.dropped++;
257 }
258 #endif
259
260 (void)fwk_interrupt_global_enable(flags);
261 }
262
fwk_log_unbuffer(void)263 int fwk_log_unbuffer(void)
264 {
265 int status = FWK_SUCCESS;
266
267 #ifdef FWK_LOG_BUFFERED
268 unsigned int flags;
269 unsigned char fetched;
270 char ch;
271
272 flags = fwk_interrupt_global_disable();
273
274 if (fwk_log_ctx.remaining == 0) {
275 /*
276 * We've finished printing whatever message we were previously on, so we
277 * need to try and fetch the next one.
278 */
279
280 bool empty = !fwk_ring_pop(
281 &fwk_log_ctx.ring,
282 (char *)&fwk_log_ctx.remaining,
283 sizeof(fwk_log_ctx.remaining));
284
285 if (empty) {
286 /*
287 * At this point we've cleared the buffer of any remaining messages.
288 * If we were forced to drop any messages prior to this point, now
289 * is a good time to let the user know.
290 */
291
292 if (fwk_log_ctx.dropped > 0) {
293 fwk_log_printf(
294 "[FWK] ... and %u more messages...", fwk_log_ctx.dropped);
295
296 fwk_log_ctx.dropped = 0;
297
298 status = FWK_PENDING;
299 }
300
301 goto exit;
302 }
303 }
304
305 /*
306 * Grab the next character from the ring buffer and try to print it.
307 * Printing the character successfully will result in a pending return value
308 * even if it is the last character in the message - the next call to this
309 * function will run the logic above to finalize the message.
310 */
311
312 fetched = fwk_ring_pop(&fwk_log_ctx.ring, &ch, sizeof(ch));
313 fwk_assert(fetched == sizeof(char));
314
315 status = fwk_io_putch(fwk_log_stream, ch);
316 if (status == FWK_SUCCESS) {
317 fwk_log_ctx.remaining--;
318
319 status = FWK_PENDING;
320 }
321
322 exit:
323 fwk_interrupt_global_enable(flags);
324 #endif
325
326 return status;
327 }
328
fwk_log_flush(void)329 void fwk_log_flush(void)
330 {
331 #ifdef FWK_LOG_BUFFERED
332 unsigned int flags;
333 int status;
334
335 flags = fwk_interrupt_global_disable();
336
337 do {
338 status = fwk_log_unbuffer();
339 } while (status == FWK_PENDING);
340
341 fwk_interrupt_global_enable(flags);
342 #endif
343 }
344