1 /*
2 * Arm SCP/MCP Software
3 * Copyright (c) 2020-2023, 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[] = FMW_LOG_ENDLINE_STR;
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 buffer_size -= FWK_ARRAY_SIZE(FWK_LOG_TERMINATOR);
103
104 /*
105 * We start by generating a timestamp for the message using the number of
106 * nanoseconds since boot.
107 */
108
109 timestamp = fwk_time_current();
110 duration = fwk_time_stamp_duration(timestamp);
111
112 /*
113 * Newlib support for printing 64-bit integers with `printf()` is
114 * optional and actually disabled by default in GNU Arm Embedded. To
115 * print the timestamp values under this configuration we need to
116 * truncate the timestamp values to 32 bits.
117 *
118 * This gives us a theoretical maximum of 136 years' worth of seconds on the
119 * timestamp, which is still plenty.
120 */
121
122 duration_s = (uint32_t)fwk_time_duration_s(duration);
123 duration_us = (uint32_t)fwk_time_duration_us(duration % FWK_S(1));
124
125 /* Generate the timestamp at the beginning of the buffer */
126 length = (size_t)snprintf(
127 buffer,
128 buffer_size,
129 "[%5" PRIu32 ".%06" PRIu32 "] ",
130 duration_s,
131 duration_us);
132 fwk_assert(length < buffer_size);
133
134 /*
135 * We then need to `snprintf()` the message into a temporary buffer because
136 * we need to manipulate it before we print or store it.
137 */
138
139 length += vsnprintf(buffer + length, buffer_size - length, format, *args);
140 length = FWK_MIN(length, buffer_size - 1);
141
142 /*
143 * Lastly, we follow through on the termination defined by
144 * `FWK_LOG_TERMINATOR`.
145 */
146
147 (void)memcpy(
148 buffer + length, FWK_LOG_TERMINATOR, sizeof(FWK_LOG_TERMINATOR));
149 }
150
fwk_log_snprintf(size_t buffer_size,char buffer[buffer_size],const char * format,...)151 static void fwk_log_snprintf(
152 size_t buffer_size,
153 char buffer[buffer_size],
154 const char *format,
155 ...)
156 {
157 va_list args;
158
159 va_start(args, format);
160 fwk_log_vsnprintf(buffer_size, buffer, format, &args);
161 va_end(args);
162 }
163
fwk_log_banner(void)164 static bool fwk_log_banner(void)
165 {
166 char buffer[FMW_LOG_COLUMNS];
167
168 #if defined(FMW_LOG_CUSTOM_BANNER)
169 const char *banner[] = { FMW_LOG_CUSTOM_BANNER_STRING };
170 #elif !defined(FMW_LOG_MINIMAL_BANNER)
171 const char *banner[] = {
172 " ___ ___ ___ __ _",
173 "/ __|/ __| _ \\___ / _(_)_ _ _ ____ __ ____ _ _ _ ___",
174 "\\__ | (__| _|___| _| | '_| ' \\ V V / _` | '_/ -_)",
175 "|___/\\___|_| |_| |_|_| |_|_|_\\_/\\_/\\__,_|_| \\___|",
176 "",
177 BUILD_VERSION_DESCRIBE_STRING,
178 "",
179 };
180 #else
181 const char *banner[] = { "SCP-firmware " BUILD_VERSION_DESCRIBE_STRING,
182 "" };
183 #endif
184 for (unsigned int i = 0; i < FWK_ARRAY_SIZE(banner); i++) {
185 fwk_log_snprintf(sizeof(buffer), buffer, "%s", banner[i]);
186 if (fwk_io_puts(fwk_log_stream, buffer) != FWK_SUCCESS) {
187 return false;
188 }
189 }
190
191 return true;
192 }
193
fwk_log_printf(const char * format,...)194 void fwk_log_printf(const char *format, ...)
195 {
196 unsigned int flags;
197 static bool banner = false;
198
199 char buffer[FMW_LOG_COLUMNS + sizeof(FWK_LOG_TERMINATOR)];
200
201 va_list args;
202
203 flags = fwk_interrupt_global_disable(); /* Facilitate reentrancy */
204
205 /*
206 * We don't have any way for the log drain entity to communicate that it is
207 * ready to accept prints, so our best bet for printing the banner is just
208 * to keep trying to do it before every call to this function, until it
209 * succeeds.
210 */
211
212 if (!banner) {
213 banner = fwk_log_banner();
214 }
215
216 va_start(args, format);
217 fwk_log_vsnprintf(sizeof(buffer), buffer, format, &args);
218 va_end(args);
219
220 #ifdef FWK_LOG_BUFFERED
221 /*
222 * Buffer the message that we've received so that the scheduler can choose
223 * when we do the heavy-lifting (typically once we're in an idle state).
224 */
225
226 bool dropped = !fwk_log_buffer(&fwk_log_ctx.ring, buffer);
227 if (dropped) {
228 /*
229 * If we don't have enough room left in the buffer, then we're out of
230 * luck. We don't want to spend what are likely to be precious cycles
231 * printing on the always-on backend, so our best option is simply to
232 * mark the message as dropped and move on.
233 */
234
235 fwk_log_ctx.dropped++;
236 }
237 #else
238 int status = fwk_io_puts(fwk_log_stream, buffer);
239 if (status != FWK_SUCCESS) {
240 fwk_log_ctx.dropped++;
241 }
242 #endif
243
244 (void)fwk_interrupt_global_enable(flags);
245 }
246
fwk_log_unbuffer(void)247 int fwk_log_unbuffer(void)
248 {
249 int status = FWK_SUCCESS;
250
251 #ifdef FWK_LOG_BUFFERED
252 unsigned int flags;
253 unsigned char fetched;
254 char ch;
255
256 flags = fwk_interrupt_global_disable();
257
258 if (fwk_log_ctx.remaining == 0) {
259 /*
260 * We've finished printing whatever message we were previously on, so we
261 * need to try and fetch the next one.
262 */
263
264 bool empty = !fwk_ring_pop(
265 &fwk_log_ctx.ring,
266 (char *)&fwk_log_ctx.remaining,
267 sizeof(fwk_log_ctx.remaining));
268
269 if (empty) {
270 /*
271 * At this point we've cleared the buffer of any remaining messages.
272 * If we were forced to drop any messages prior to this point, now
273 * is a good time to let the user know.
274 */
275
276 if (fwk_log_ctx.dropped > 0) {
277 fwk_log_printf(
278 "[FWK] ... and %u more messages...", fwk_log_ctx.dropped);
279
280 fwk_log_ctx.dropped = 0;
281
282 status = FWK_PENDING;
283 }
284
285 goto exit;
286 }
287 }
288
289 /*
290 * Grab the next character from the ring buffer and try to print it.
291 * Printing the character successfully will result in a pending return value
292 * even if it is the last character in the message - the next call to this
293 * function will run the logic above to finalize the message.
294 */
295
296 fetched = fwk_ring_peek(&fwk_log_ctx.ring, &ch, sizeof(ch));
297 fwk_assert(fetched == sizeof(char));
298
299 status = fwk_io_putch_nowait(fwk_log_stream, ch);
300 switch (status) {
301 case FWK_SUCCESS:
302 /*
303 * If the character was successfully printed, then we remove it from
304 * the buffer.
305 */
306 fwk_ring_pop(&fwk_log_ctx.ring, &ch, sizeof(ch));
307 fwk_log_ctx.remaining--;
308 status = FWK_PENDING;
309 break;
310 case FWK_E_BUSY:
311 /* If the resource is busy, we keep the character in the buffer. */
312 status = FWK_PENDING;
313 break;
314 default:
315 break;
316 }
317
318 exit:
319 fwk_interrupt_global_enable(flags);
320 #endif
321
322 return status;
323 }
324
fwk_log_flush(void)325 void fwk_log_flush(void)
326 {
327 #ifdef FWK_LOG_BUFFERED
328 unsigned int flags;
329 int status;
330
331 flags = fwk_interrupt_global_disable();
332
333 do {
334 status = fwk_log_unbuffer();
335 } while (status == FWK_PENDING);
336
337 fwk_interrupt_global_enable(flags);
338 #endif
339 }
340