matrixfurry.com
The open source OpenXR runtime
1// Copyright 2019-2025, Collabora, Ltd.
2// Copyright 2025, NVIDIA CORPORATION.
3// SPDX-License-Identifier: BSL-1.0
4/*!
5 * @file
6 * @brief Logging functions.
7 * @author Jakob Bornecrantz <jakob@collabora.com>
8 * @ingroup aux_util
9 */
10
11#include "util/u_logging.h"
12#include "xrt/xrt_config_os.h"
13#include "xrt/xrt_config_build.h"
14
15#include "util/u_debug.h"
16#include "util/u_pretty_print.h"
17#include "u_json.h"
18#include "util/u_truncate_printf.h"
19
20#include <assert.h>
21#include <stddef.h>
22#include <stdio.h>
23#include <stdarg.h>
24
25
26/*
27 *
28 * Defines.
29 *
30 */
31
32/*
33 * Avoid 4K stack variables.
34 * https://learn.microsoft.com/en-us/windows/win32/devnotes/-win32-chkstk
35 */
36#define LOG_BUFFER_SIZE (3 * 1024)
37
38/*
39 * 16MB max binary data
40 */
41#define LOG_MAX_HEX_DUMP (0x00ffffff)
42
43#define LOG_MAX_HEX_DUMP_HUMAN_READABLE "16MB"
44
45/*
46 * Hex dumps put 16 bytes per line
47 */
48#define LOG_HEX_BYTES_PER_LINE (16)
49
50/*
51 * This is enough space for the line's bytes to be in both hex and ascii
52 */
53#define LOG_HEX_LINE_BUF_SIZE (128)
54
55
56#ifndef LOG_ANDROID_TAG_PREFIX
57#define LOG_ANDROID_TAG_PREFIX "monado"
58#endif
59
60/*
61 *
62 * Global log level functions.
63 *
64 */
65
66DEBUG_GET_ONCE_LOG_OPTION(global_log, "XRT_LOG", U_LOGGING_WARN)
67DEBUG_GET_ONCE_BOOL_OPTION(json_log, "XRT_JSON_LOG", false)
68
69enum u_logging_level
70u_log_get_global_level(void)
71{
72 return debug_get_log_option_global_log();
73}
74
75
76/*
77 *
78 * Logging file code.
79 *
80 */
81
82static FILE *g_log_file = NULL;
83
84void
85u_log_set_output_file(const char *filename)
86{
87 // While not thread safe, this function is externally synchronized.
88 if (g_log_file != NULL) {
89 FILE *tmp = g_log_file;
90 g_log_file = NULL;
91
92 fflush(tmp);
93 fclose(tmp);
94 tmp = NULL;
95 }
96
97 if (filename == NULL) {
98 return; // Turning off file logging.
99 }
100
101 g_log_file = fopen(filename, "w");
102 if (g_log_file == NULL) {
103 U_LOG_E("Failed to open '%s'", filename);
104 }
105}
106
107
108/*
109 *
110 * Logging sink.
111 *
112 */
113
114// Logging sink global data.
115static u_log_sink_func_t g_log_sink_func;
116static void *g_log_sink_data;
117
118void
119u_log_set_sink(u_log_sink_func_t func, void *data)
120{
121 g_log_sink_func = func;
122 g_log_sink_data = data;
123}
124
125#define DISPATCH_SINK(FILE, LINE, FUNC, LEVEL, FORMAT, ARGS) \
126 if (g_log_sink_func != NULL) { \
127 va_list copy; \
128 va_copy(copy, ARGS); \
129 g_log_sink_func(FILE, LINE, FUNC, LEVEL, FORMAT, copy, g_log_sink_data); \
130 va_end(copy); \
131 }
132
133
134/*
135 *
136 * Hexdump functions.
137 *
138 */
139
140static void
141u_log_hexdump_line(char *buf, size_t offset, const uint8_t *data, size_t data_size)
142{
143 char *pos = buf;
144
145 if (data_size > LOG_HEX_BYTES_PER_LINE) {
146 data_size = LOG_HEX_BYTES_PER_LINE;
147 }
148
149 pos += sprintf(pos, "%08x: ", (uint32_t)offset);
150
151 char *ascii = pos + ((ptrdiff_t)LOG_HEX_BYTES_PER_LINE * 3) + 1;
152 size_t i;
153
154 for (i = 0; i < data_size; i++) {
155 pos += sprintf(pos, "%02x ", data[i]);
156
157 if (data[i] >= ' ' && data[i] <= '~') {
158 *ascii++ = data[i];
159 } else {
160 *ascii++ = '.';
161 }
162 }
163
164 /* Pad short lines with spaces, and null terminate */
165 while (i++ < LOG_HEX_BYTES_PER_LINE) {
166 pos += sprintf(pos, " ");
167 }
168 /* Replace the first NULL terminator with a space */
169 *pos++ = ' ';
170 /* and set it after the ASCII representation */
171 *ascii++ = '\0';
172}
173
174void
175u_log_hex(const char *file,
176 int line,
177 const char *func,
178 enum u_logging_level level,
179 const uint8_t *data,
180 const size_t data_size)
181{
182 size_t offset = 0;
183
184 while (offset < data_size) {
185 char tmp[LOG_HEX_LINE_BUF_SIZE];
186 u_log_hexdump_line(tmp, offset, data + offset, data_size - offset);
187 u_log(file, line, func, level, "%s", tmp);
188
189 offset += LOG_HEX_BYTES_PER_LINE;
190 /*
191 * Limit the dump length to 16MB, this used to be 4GB which
192 * would on 32bit system always evaltuate to false. So we have
193 * the limit on something more sensible.
194 */
195 if (offset > LOG_MAX_HEX_DUMP) {
196 u_log(file, line, func, level, "Truncating output over " LOG_MAX_HEX_DUMP_HUMAN_READABLE);
197 break;
198 }
199 }
200}
201
202void
203u_log_xdev_hex(const char *file,
204 int line,
205 const char *func,
206 enum u_logging_level level,
207 struct xrt_device *xdev,
208 const uint8_t *data,
209 const size_t data_size)
210{
211 size_t offset = 0;
212
213 while (offset < data_size) {
214 char tmp[LOG_HEX_LINE_BUF_SIZE];
215 u_log_hexdump_line(tmp, offset, data + offset, data_size - offset);
216 u_log_xdev(file, line, func, level, xdev, "%s", tmp);
217
218 offset += LOG_HEX_BYTES_PER_LINE;
219 /*
220 * Limit the dump length to 16MB, this used to be 4GB which
221 * would on 32bit system always evaltuate to false. So we have
222 * the limit on something more sensible.
223 */
224 if (offset > LOG_MAX_HEX_DUMP) {
225 u_log_xdev(file, line, func, level, xdev,
226 "Truncating output over " LOG_MAX_HEX_DUMP_HUMAN_READABLE);
227 break;
228 }
229 }
230}
231
232
233/*
234 *
235 * Platform specific functions.
236 *
237 */
238
239#if defined(XRT_OS_ANDROID)
240
241#include <android/log.h>
242
243static android_LogPriority
244u_log_convert_priority(enum u_logging_level level)
245{
246 switch (level) {
247 case U_LOGGING_TRACE: return ANDROID_LOG_VERBOSE;
248 case U_LOGGING_DEBUG: return ANDROID_LOG_DEBUG;
249 case U_LOGGING_INFO: return ANDROID_LOG_INFO;
250 case U_LOGGING_WARN: return ANDROID_LOG_WARN;
251 case U_LOGGING_ERROR: return ANDROID_LOG_ERROR;
252 case U_LOGGING_RAW: return ANDROID_LOG_INFO;
253 default: break;
254 }
255 return ANDROID_LOG_INFO;
256}
257
258#elif defined(XRT_OS_WINDOWS)
259
260#include <debugapi.h>
261
262#else
263
264#include <unistd.h>
265
266#endif
267
268
269/*
270 *
271 * Helper functions.
272 *
273 */
274
275#define CHECK_RET_AND_UPDATE_STATE() \
276 do { \
277 if (ret < 0) { \
278 return ret; \
279 } \
280 \
281 printed += ret; /* Is not negative, checked above. */ \
282 remaining -= ret; \
283 buf += ret; /* Continue in the buffer from where we left off. */ \
284 } while (false);
285
286#ifdef XRT_FEATURE_COLOR_LOG
287#define COLOR_TRACE "\033[2m"
288#define COLOR_DEBUG "\033[36m"
289#define COLOR_INFO "\033[32m"
290#define COLOR_WARN "\033[33m"
291#define COLOR_ERROR "\033[31m"
292#define COLOR_RESET "\033[0m"
293
294static int
295print_prefix_color(const char *func, enum u_logging_level level, char *buf, int remaining)
296{
297 switch (level) {
298 case U_LOGGING_TRACE: return u_truncate_snprintf(buf, remaining, COLOR_TRACE "TRACE " COLOR_RESET);
299 case U_LOGGING_DEBUG: return u_truncate_snprintf(buf, remaining, COLOR_DEBUG "DEBUG " COLOR_RESET);
300 case U_LOGGING_INFO: return u_truncate_snprintf(buf, remaining, COLOR_INFO " INFO " COLOR_RESET);
301 case U_LOGGING_WARN: return u_truncate_snprintf(buf, remaining, COLOR_WARN " WARN " COLOR_RESET);
302 case U_LOGGING_ERROR: return u_truncate_snprintf(buf, remaining, COLOR_ERROR "ERROR " COLOR_RESET);
303 case U_LOGGING_RAW: return 0;
304 default: return 0;
305 }
306}
307#endif
308
309static int
310print_prefix_mono(const char *func, enum u_logging_level level, char *buf, int remaining)
311{
312 switch (level) {
313 case U_LOGGING_TRACE: return u_truncate_snprintf(buf, remaining, "TRACE ");
314 case U_LOGGING_DEBUG: return u_truncate_snprintf(buf, remaining, "DEBUG ");
315 case U_LOGGING_INFO: return u_truncate_snprintf(buf, remaining, " INFO ");
316 case U_LOGGING_WARN: return u_truncate_snprintf(buf, remaining, " WARN ");
317 case U_LOGGING_ERROR: return u_truncate_snprintf(buf, remaining, "ERROR ");
318 case U_LOGGING_RAW: return 0;
319 default: return 0;
320 }
321}
322
323static int
324print_prefix(const char *func, enum u_logging_level level, char *buf, int remaining)
325{
326 int printed = 0;
327 int ret = 0;
328
329#ifdef XRT_FEATURE_COLOR_LOG
330 if (g_log_file == NULL && isatty(STDERR_FILENO)) {
331 ret = print_prefix_color(func, level, buf, remaining);
332 } else {
333 ret = print_prefix_mono(func, level, buf, remaining);
334 }
335#else
336 ret = print_prefix_mono(func, level, buf, remaining);
337#endif
338
339 // Does what it says.
340 CHECK_RET_AND_UPDATE_STATE();
341
342 // Print the function name.
343 if (level != U_LOGGING_RAW && func != NULL) {
344 ret = u_truncate_snprintf(buf, remaining, "[%s] ", func);
345 }
346
347 // Does what it says.
348 CHECK_RET_AND_UPDATE_STATE();
349
350 // Total printed characters.
351 return printed;
352}
353
354static int
355log_as_json(const char *file, const char *func, enum u_logging_level level, const char *format, va_list args)
356{
357 cJSON *root = cJSON_CreateObject();
358
359 char *level_s;
360 switch (level) {
361 case U_LOGGING_TRACE: level_s = "trace"; break;
362 case U_LOGGING_DEBUG: level_s = "debug"; break;
363 case U_LOGGING_INFO: level_s = "info"; break;
364 case U_LOGGING_WARN: level_s = "warn"; break;
365 case U_LOGGING_ERROR: level_s = "error"; break;
366 default: level_s = "raw"; break;
367 }
368
369 // Add metadata.
370 cJSON_AddItemToObject(root, "level", cJSON_CreateString(level_s));
371 cJSON_AddItemToObject(root, "file", cJSON_CreateString(file));
372 cJSON_AddItemToObject(root, "func", cJSON_CreateString(func));
373
374 // Add message.
375 char msg_buf[LOG_BUFFER_SIZE];
376 u_truncate_vsnprintf(msg_buf, LOG_BUFFER_SIZE, format, args);
377 cJSON_AddItemToObject(root, "message", cJSON_CreateString(msg_buf));
378
379 // Get string and print to stderr.
380 char *out = cJSON_PrintUnformatted(root);
381 int printed = fprintf(stderr, "%s\n", out);
382
383 // Clean up after us.
384 cJSON_Delete(root);
385 cJSON_free(out);
386
387 return printed;
388}
389
390static int
391do_print(const char *file, int line, const char *func, enum u_logging_level level, const char *format, va_list args)
392{
393 if (debug_get_bool_option_json_log()) {
394 return log_as_json(file, func, level, format, args);
395 }
396
397 char storage[LOG_BUFFER_SIZE];
398
399 int remaining = sizeof(storage) - 2; // 2 for \n\0
400 int printed = 0;
401 char *buf = storage; // We update the pointer.
402 int ret = 0;
403
404 // The prefix of the log.
405 ret = print_prefix(func, level, buf, remaining);
406
407 // Does what it says.
408 CHECK_RET_AND_UPDATE_STATE();
409
410 ret = u_truncate_vsnprintf(buf, remaining, format, args);
411
412 // Does what it says.
413 CHECK_RET_AND_UPDATE_STATE();
414
415 /*
416 * The variable storage now holds the entire null-terminated message,
417 * but without a new-line character, proceed to output it.
418 */
419 assert(storage[printed] == '\0');
420
421
422#ifdef XRT_OS_ANDROID
423 android_LogPriority prio = u_log_convert_priority(level);
424
425 char storage_tag[256];
426 int tag_ret = u_truncate_snprintf(storage_tag, sizeof(storage_tag), LOG_ANDROID_TAG_PREFIX ".%s", func);
427 if (tag_ret < 0) {
428 __android_log_write(prio, func, storage);
429 } else {
430 __android_log_write(prio, storage_tag, storage);
431 }
432#elif defined XRT_OS_WINDOWS || defined XRT_OS_LINUX
433
434 // We want a newline, so add it, then null-terminate again.
435 storage[printed++] = '\n';
436 storage[printed] = '\0'; // Don't count zero termination as printed.
437
438#if defined XRT_OS_WINDOWS
439 // Visual Studio output needs the newline char
440 OutputDebugStringA(storage);
441#endif
442
443 FILE *output = g_log_file != NULL ? g_log_file : stderr;
444 fwrite(storage, printed, 1, output);
445
446#if defined(XRT_OS_WINDOWS)
447 /*
448 * Windows like to buffer messages, call flush here to make sure all
449 * logs gets written out in case of sudden exits and crashes.
450 */
451 fflush(output);
452#endif
453
454#else
455#error "Port needed for logging function"
456#endif
457
458 return printed;
459}
460
461
462/*
463 *
464 * 'Exported' functions.
465 *
466 */
467
468void
469u_log_print_result(enum u_logging_level cond_level,
470 const char *file,
471 int line,
472 const char *calling_fn,
473 xrt_result_t xret,
474 const char *called_fn)
475{
476 bool success = xret == XRT_SUCCESS;
477 enum u_logging_level level = success ? U_LOGGING_INFO : U_LOGGING_ERROR;
478
479 // Should we be logging?
480 if (level < cond_level) {
481 return;
482 }
483
484 struct u_pp_sink_stack_only sink;
485 u_pp_delegate_t dg = u_pp_sink_stack_only_init(&sink);
486
487 if (success) {
488 u_pp(dg, "%s: ", called_fn);
489 } else {
490 u_pp(dg, "%s failed: ", called_fn);
491 }
492
493 u_pp_xrt_result(dg, xret);
494 u_pp(dg, " [%s:%i]", file, line);
495
496 u_log(file, line, calling_fn, level, "%s", sink.buffer);
497}
498
499static u_log_filter_func_t g_filter = NULL;
500
501void
502u_log_set_filter(u_log_filter_func_t filter)
503{
504 g_filter = filter;
505}
506
507void
508u_log(const char *file, int line, const char *func, enum u_logging_level level, const char *format, ...)
509{
510 va_list args;
511 // Check filter first
512 if (g_filter != NULL && !g_filter(file, line, func, level)) {
513 return; // Skip this message
514 }
515
516 va_start(args, format);
517 DISPATCH_SINK(file, line, func, level, format, args);
518 do_print(file, line, func, level, format, args);
519 va_end(args);
520}
521
522void
523u_log_xdev(const char *file,
524 int line,
525 const char *func,
526 enum u_logging_level level,
527 struct xrt_device *xdev,
528 const char *format,
529 ...)
530{
531 va_list args;
532 // Check filter first
533 if (g_filter != NULL && !g_filter(file, line, func, level)) {
534 return; // Skip this message
535 }
536 va_start(args, format);
537 DISPATCH_SINK(file, line, func, level, format, args);
538 do_print(file, line, func, level, format, args);
539 va_end(args);
540}