Commit | Line | Data |
---|---|---|
71436ae4 SM |
1 | /* |
2 | * SPDX-License-Identifier: MIT | |
3 | * | |
4 | * Copyright (c) 2016 wonder-mice | |
5 | * Copyright (c) 2016-2023 Philippe Proulx <pproulx@efficios.com> | |
6 | * | |
7 | * This is very inspired by zf_log.c (see | |
8 | * <https://github.com/wonder-mice/zf_log/>), but modified (mostly | |
9 | * stripped down) for the use cases of Babeltrace. | |
10 | */ | |
11 | ||
12 | #include <ctype.h> | |
13 | #include <errno.h> | |
14 | #include <glib.h> | |
15 | #include <stdint.h> | |
16 | #include <stdio.h> | |
17 | #include <string.h> | |
18 | #include <sys/time.h> | |
19 | #include <time.h> | |
20 | #include <unistd.h> | |
21 | ||
22 | #if defined(_WIN32) || defined(_WIN64) | |
23 | # include <windows.h> | |
24 | #endif | |
25 | ||
26 | #ifdef __linux__ | |
27 | # include <sys/prctl.h> | |
28 | # include <sys/syscall.h> | |
29 | #endif | |
30 | ||
31 | #ifdef __MACH__ | |
32 | # include <pthread.h> | |
33 | #endif | |
34 | ||
35 | #ifdef __GNU__ | |
36 | # include <mach.h> | |
37 | #endif | |
38 | ||
27b0e85b MJ |
39 | #ifdef __FreeBSD__ |
40 | # include <sys/thr.h> | |
41 | #endif | |
42 | ||
71436ae4 SM |
43 | #include "common/assert.h" |
44 | #include "common/common.h" | |
45 | #include "common/macros.h" | |
46 | #include "compat/time.h" | |
47 | ||
48 | #include "log-api.h" | |
49 | ||
50 | #ifdef __CYGWIN__ | |
51 | extern unsigned long pthread_getsequence_np(pthread_t *); | |
52 | #endif | |
53 | ||
54 | /* | |
55 | * Thread-local logging message buffer to put the next message and write | |
56 | * it with a single system call. | |
57 | */ | |
58 | static __thread char msg_buf[4 * 4096]; | |
59 | ||
60 | /* | |
61 | * Returns the number of available bytes in `msg_buf` considering the | |
62 | * writing position `at`. | |
63 | */ | |
64 | static inline | |
65 | size_t avail_msg_buf_bytes(char *at) | |
66 | { | |
67 | return msg_buf + sizeof(msg_buf) - at; | |
68 | } | |
69 | ||
70 | /* | |
71 | * Appends the character `ch` to `msg_buf`. | |
72 | */ | |
73 | static inline | |
74 | void append_char_to_msg_buf(char ** const at, const char ch) | |
75 | { | |
76 | **at = ch; | |
77 | (*at)++; | |
78 | } | |
79 | ||
80 | /* | |
81 | * Appends a space character to `msg_buf`. | |
82 | */ | |
83 | static inline | |
84 | void append_sp_to_msg_buf(char ** const at) | |
85 | { | |
86 | append_char_to_msg_buf(at, ' '); | |
87 | } | |
88 | ||
89 | /* | |
90 | * Appends the null-terminated string `str` to `msg_buf`. | |
91 | */ | |
92 | static inline | |
93 | void append_str_to_msg_buf(char ** const at, const char * const str) | |
94 | { | |
95 | const size_t len = strlen(str); | |
96 | ||
97 | memcpy(*at, str, len); | |
98 | *at += len; | |
99 | } | |
100 | ||
101 | /* | |
102 | * Formats the unsigned integer `val` with sprintf() using `fmt` and | |
103 | * appends the resulting string to `msg_buf`. | |
104 | */ | |
105 | static inline | |
106 | void append_uint_to_msg_buf(char ** const at, const char * const fmt, | |
107 | const unsigned int val) | |
108 | { | |
109 | #pragma GCC diagnostic push | |
110 | #pragma GCC diagnostic ignored "-Wformat-nonliteral" | |
111 | const int written_len = sprintf(*at, fmt, val); | |
112 | #pragma GCC diagnostic pop | |
113 | ||
114 | BT_ASSERT_DBG(written_len > 0); | |
115 | *at += (size_t) written_len; | |
116 | } | |
117 | ||
118 | /* | |
119 | * Thread-local cache of seconds and milliseconds to formatted date/time | |
120 | * string (null terminated). | |
121 | * | |
122 | * This is often useful because many log messages may happen during the | |
123 | * same millisecond. | |
124 | * | |
125 | * Does not need any kind of protection since it's TLS. | |
126 | */ | |
127 | struct date_time_cache { | |
128 | uint64_t s; | |
129 | uint32_t ms; | |
130 | char str[128]; | |
131 | }; | |
132 | ||
133 | static __thread struct date_time_cache date_time_cache = {0}; | |
134 | ||
135 | static | |
136 | const char *date_time_cache_get(const struct timeval tv) | |
137 | { | |
138 | const uint64_t s = (uint64_t) tv.tv_sec; | |
139 | const uint32_t ms = (uint32_t) (tv.tv_usec / 1000); | |
140 | ||
141 | if (date_time_cache.s != s || date_time_cache.ms != ms) { | |
142 | /* Add to cache now */ | |
143 | struct tm tm; | |
144 | const time_t time_s = (time_t) tv.tv_sec; | |
145 | ||
146 | date_time_cache.s = (uint64_t) tv.tv_sec; | |
147 | date_time_cache.ms = (uint32_t) (tv.tv_usec / 1000); | |
148 | (void) bt_localtime_r(&time_s, &tm); | |
149 | (void) sprintf(date_time_cache.str, "%02u-%02u %02u:%02u:%02u.%03u", | |
150 | tm.tm_mon + 1, tm.tm_mday, | |
151 | tm.tm_hour, tm.tm_min, tm.tm_sec, date_time_cache.ms); | |
152 | } | |
153 | ||
154 | return date_time_cache.str; | |
155 | } | |
156 | ||
157 | /* | |
158 | * Appends a formatted date/time for `tv` to `msg_buf`. | |
159 | */ | |
160 | static inline | |
161 | void append_date_time_to_msg_buf(char ** const at, const struct timeval tv) | |
162 | { | |
163 | const char *str = date_time_cache_get(tv); | |
164 | ||
165 | append_str_to_msg_buf(at, str); | |
166 | } | |
167 | ||
168 | /* | |
169 | * Appends the PID and TID to `msg_buf`. | |
170 | */ | |
171 | static inline | |
172 | void append_pid_tid_to_msg_buf(char ** const at) | |
173 | { | |
174 | const unsigned int pid = (unsigned int) getpid(); | |
175 | unsigned int tid; | |
176 | ||
177 | /* Look at this beautiful portability */ | |
178 | #if defined(_WIN32) || defined(_WIN64) | |
179 | tid = (unsigned int) GetCurrentThreadId(); | |
180 | #elif defined(__CYGWIN__) | |
181 | { | |
182 | pthread_t thr = pthread_self(); | |
183 | ||
184 | tid = (unsigned int) pthread_getsequence_np(&thr); | |
185 | } | |
186 | #elif defined(__sun__) | |
187 | tid = (unsigned int) pthread_self(); | |
188 | #elif defined(__linux__) | |
189 | tid = (unsigned int) syscall(SYS_gettid); | |
190 | #elif defined(__APPLE__) && defined(__MACH__) | |
191 | tid = (unsigned int) pthread_mach_thread_np(pthread_self()); | |
192 | #elif defined(__GNU__) | |
193 | { | |
194 | mach_port_t mach_port = mach_thread_self(); | |
195 | ||
196 | mach_port_deallocate(mach_task_self(), mach_port); | |
197 | tid = (unsigned int) mach_port; | |
198 | } | |
27b0e85b MJ |
199 | #elif defined(__FreeBSD__) |
200 | { | |
201 | long ltid; | |
202 | ||
203 | thr_self(<id); | |
204 | ||
205 | /* | |
206 | * The thread ID is an integer in the range from | |
207 | * `PID_MAX + 2` (100001) to `INT_MAX`. | |
208 | */ | |
209 | tid = (unsigned int) ltid; | |
210 | } | |
71436ae4 SM |
211 | #else |
212 | # error "Platform not supported" | |
213 | #endif | |
214 | ||
215 | /* Append them now */ | |
216 | append_uint_to_msg_buf(at, "%u", pid); | |
217 | append_sp_to_msg_buf(at); | |
218 | append_uint_to_msg_buf(at, "%u", tid); | |
219 | } | |
220 | ||
221 | /* | |
222 | * Writes the initial part of the log message to `msg_buf`, without the | |
223 | * message and without resetting the terminal color). | |
224 | */ | |
225 | static | |
226 | void common_write_init(char ** const at, const char * const file_name, | |
227 | const char * const func_name, const unsigned int line_no, | |
228 | const enum bt_log_level lvl, const char * const tag) | |
229 | { | |
230 | const char *color_p = ""; | |
231 | struct timeval tv; | |
232 | ||
233 | /* Get time immediately */ | |
234 | gettimeofday(&tv, 0); | |
235 | ||
236 | /* Write the terminal color code to use, if any */ | |
237 | switch (lvl) { | |
238 | case BT_LOG_INFO: | |
239 | color_p = bt_common_color_fg_blue(); | |
240 | break; | |
241 | case BT_LOG_WARNING: | |
242 | color_p = bt_common_color_fg_yellow(); | |
243 | break; | |
244 | case BT_LOG_ERROR: | |
245 | case BT_LOG_FATAL: | |
246 | color_p = bt_common_color_fg_red(); | |
247 | break; | |
248 | default: | |
249 | break; | |
250 | } | |
251 | ||
252 | append_str_to_msg_buf(at, color_p); | |
253 | ||
254 | /* Write date/time */ | |
255 | append_date_time_to_msg_buf(at, tv); | |
256 | append_sp_to_msg_buf(at); | |
257 | ||
258 | /* Write PID/TID */ | |
259 | append_pid_tid_to_msg_buf(at); | |
260 | append_sp_to_msg_buf(at); | |
261 | ||
262 | /* Write log level letter */ | |
263 | append_char_to_msg_buf(at, bt_log_get_letter_from_level(lvl)); | |
264 | append_sp_to_msg_buf(at); | |
265 | ||
266 | /* Write tag */ | |
267 | if (tag) { | |
268 | append_str_to_msg_buf(at, tag); | |
269 | append_sp_to_msg_buf(at); | |
270 | } | |
271 | ||
272 | /* Write source location */ | |
273 | append_str_to_msg_buf(at, func_name); | |
274 | append_char_to_msg_buf(at, '@'); | |
275 | append_str_to_msg_buf(at, file_name); | |
276 | append_uint_to_msg_buf(at, ":%u", line_no); | |
277 | append_sp_to_msg_buf(at); | |
278 | } | |
279 | ||
280 | /* | |
281 | * Writes the final part of the log message to `msg_buf` (resets the | |
282 | * terminal color and appends a newline), and then writes the whole log | |
283 | * message to the standard error. | |
284 | */ | |
285 | static | |
286 | void common_write_fini(char ** const at) | |
287 | { | |
288 | append_str_to_msg_buf(at, bt_common_color_reset()); | |
289 | append_char_to_msg_buf(at, '\n'); | |
290 | (void) write(STDERR_FILENO, msg_buf, *at - msg_buf); | |
291 | } | |
292 | ||
293 | void bt_log_write(const char * const file_name, const char * const func_name, | |
294 | const unsigned int line_no, const enum bt_log_level lvl, | |
295 | const char * const tag, const char * const msg) | |
296 | { | |
297 | char *at = msg_buf; | |
298 | ||
299 | common_write_init(&at, file_name, func_name, line_no, lvl, tag); | |
300 | append_str_to_msg_buf(&at, msg); | |
301 | common_write_fini(&at); | |
302 | } | |
303 | ||
304 | _BT_LOG_PRINTFLIKE(6, 0) | |
305 | static | |
306 | void write_vprintf(const char * const file_name, const char * const func_name, | |
307 | const unsigned int line_no, const enum bt_log_level lvl, | |
308 | const char * const tag, const char * const fmt, va_list args) | |
309 | { | |
310 | char *at = msg_buf; | |
311 | int written_len; | |
312 | ||
313 | common_write_init(&at, file_name, func_name, line_no, lvl, tag); | |
314 | written_len = vsnprintf(at, avail_msg_buf_bytes(at) - 16, | |
315 | fmt, args); | |
316 | if (written_len > 0) { | |
317 | at += (size_t) written_len; | |
318 | } | |
319 | ||
320 | common_write_fini(&at); | |
321 | } | |
322 | ||
323 | void bt_log_write_printf(const char * const file_name, | |
324 | const char * const func_name, const unsigned int line_no, | |
325 | const enum bt_log_level lvl, const char * const tag, | |
326 | const char * const fmt, ...) | |
327 | { | |
328 | va_list va; | |
329 | ||
330 | va_start(va, fmt); | |
331 | write_vprintf(file_name, func_name, line_no, lvl, tag, fmt, va); | |
332 | va_end(va); | |
333 | } | |
334 | ||
335 | /* | |
336 | * Writes the initial part of the log message to `msg_buf`, including | |
337 | * the initial message and `errno` string, without the message and | |
338 | * without resetting the terminal color). | |
339 | */ | |
340 | static | |
341 | void common_write_errno_init(char ** const at, const char * const file_name, | |
342 | const char * const func_name, const unsigned int line_no, | |
343 | const enum bt_log_level lvl, const char * const tag, | |
344 | const char * const init_msg) | |
345 | { | |
346 | BT_ASSERT_DBG(errno != 0); | |
347 | const char * const errno_msg = g_strerror(errno); | |
348 | ||
349 | common_write_init(at, file_name, func_name, line_no, lvl, tag); | |
350 | append_str_to_msg_buf(at, init_msg); | |
351 | append_char_to_msg_buf(at, ':'); | |
352 | append_sp_to_msg_buf(at); | |
353 | append_str_to_msg_buf(at, errno_msg); | |
354 | } | |
355 | ||
356 | void bt_log_write_errno(const char * const file_name, | |
357 | const char * const func_name, const unsigned int line_no, | |
358 | const enum bt_log_level lvl, const char * const tag, | |
359 | const char * const init_msg, const char * const msg) | |
360 | { | |
361 | char *at = msg_buf; | |
362 | ||
363 | common_write_errno_init(&at, file_name, func_name, line_no, lvl, | |
364 | tag, init_msg); | |
365 | append_str_to_msg_buf(&at, msg); | |
366 | common_write_fini(&at); | |
367 | } | |
368 | ||
369 | void bt_log_write_errno_printf(const char * const file_name, | |
370 | const char * const func_name, const unsigned int line_no, | |
371 | const enum bt_log_level lvl, const char * const tag, | |
372 | const char * const init_msg, const char * const fmt, ...) | |
373 | { | |
374 | char *at = msg_buf; | |
375 | int written_len; | |
376 | va_list va; | |
377 | ||
378 | common_write_errno_init(&at, file_name, func_name, line_no, lvl, | |
379 | tag, init_msg); | |
380 | va_start(va, fmt); | |
381 | written_len = vsnprintf(at, avail_msg_buf_bytes(at) - 16, fmt, va); | |
382 | va_end(va); | |
383 | if (written_len > 0) { | |
384 | at += (size_t) written_len; | |
385 | } | |
386 | ||
387 | common_write_fini(&at); | |
388 | } | |
389 | ||
390 | /* | |
391 | * Logs `mem_len` bytes of `mem_data` on a single line. | |
392 | */ | |
393 | static | |
394 | void write_mem_line(const char * const file_name, const char * const func_name, | |
395 | const unsigned int line_no, const enum bt_log_level lvl, | |
396 | const char * const tag, const uint8_t * const mem_data, | |
397 | const size_t mem_len, const size_t max_mem_line_len) | |
398 | { | |
399 | static const char * const hex_chars = "0123456789abcdef"; | |
400 | char *at = msg_buf; | |
401 | size_t i; | |
402 | ||
403 | common_write_init(&at, file_name, func_name, line_no, lvl, tag); | |
404 | ||
405 | /* Write hexadecimal representation */ | |
406 | for (i = 0; i < mem_len; i++) { | |
407 | const uint8_t byte = mem_data[i]; | |
408 | ||
409 | /* Write nibble */ | |
410 | append_char_to_msg_buf(&at, hex_chars[byte >> 4]); | |
411 | append_char_to_msg_buf(&at, hex_chars[byte & 0xf]); | |
412 | ||
413 | /* Add a space */ | |
414 | append_sp_to_msg_buf(&at); | |
415 | } | |
416 | ||
417 | /* Insert spaces to align the following ASCII representation */ | |
418 | for (i = 0; i < max_mem_line_len - mem_len; i++) { | |
419 | append_sp_to_msg_buf(&at); | |
420 | append_sp_to_msg_buf(&at); | |
421 | append_sp_to_msg_buf(&at); | |
422 | } | |
423 | ||
424 | /* Insert a vertical line between the representations */ | |
425 | append_str_to_msg_buf(&at, "| "); | |
426 | ||
427 | /* Write the ASCII representation */ | |
428 | for (i = 0; i < mem_len; i++) { | |
429 | const uint8_t byte = mem_data[i]; | |
430 | ||
431 | if (isprint(byte)) { | |
432 | append_char_to_msg_buf(&at, (char) byte); | |
433 | } else { | |
434 | /* Non-printable character */ | |
435 | append_char_to_msg_buf(&at, '.'); | |
436 | } | |
437 | } | |
438 | ||
439 | common_write_fini(&at); | |
440 | } | |
441 | ||
442 | /* | |
443 | * Logs `mem_len` bytes of `mem_data` on one or more lines. | |
444 | */ | |
445 | static | |
446 | void write_mem_lines(const char * const file_name, const char * const func_name, | |
447 | const unsigned int line_no, const enum bt_log_level lvl, | |
448 | const char * const tag, const uint8_t * const mem_data, | |
449 | const size_t mem_len) | |
450 | { | |
451 | const uint8_t *mem_at = mem_data; | |
452 | size_t rem_mem_len = mem_len; | |
453 | ||
454 | if (!mem_data || mem_len == 0) { | |
455 | /* Nothing to write */ | |
456 | goto end; | |
457 | } | |
458 | ||
459 | while (rem_mem_len > 0) { | |
460 | static const size_t max_mem_line_len = 16; | |
461 | ||
462 | /* Number of bytes to write on this line */ | |
463 | const size_t mem_line_len = rem_mem_len > max_mem_line_len ? | |
464 | max_mem_line_len : rem_mem_len; | |
465 | ||
466 | /* Log those bytes */ | |
467 | write_mem_line(file_name, func_name, line_no, lvl, tag, | |
468 | mem_at, mem_line_len, max_mem_line_len); | |
469 | ||
470 | /* Adjust for next iteration */ | |
471 | rem_mem_len -= mem_line_len; | |
472 | mem_at += mem_line_len; | |
473 | } | |
474 | ||
475 | end: | |
476 | return; | |
477 | } | |
478 | ||
479 | void bt_log_write_mem(const char * const file_name, const char * const func_name, | |
480 | const unsigned int line_no, const enum bt_log_level lvl, | |
481 | const char * const tag, const void * const mem_data, | |
482 | const size_t mem_len, const char * const msg) | |
483 | { | |
484 | bt_log_write(file_name, func_name, line_no, lvl, tag, msg); | |
485 | write_mem_lines(file_name, func_name, line_no, lvl, tag, | |
486 | mem_data, mem_len); | |
487 | } | |
488 | ||
489 | void bt_log_write_mem_printf(const char * const file_name, | |
490 | const char * const func_name, const unsigned int line_no, | |
491 | const enum bt_log_level lvl, const char * const tag, | |
492 | const void * const mem_data, const size_t mem_len, | |
493 | const char * const fmt, ...) | |
494 | { | |
495 | va_list va; | |
496 | ||
497 | va_start(va, fmt); | |
498 | write_vprintf(file_name, func_name, line_no, lvl, tag, fmt, va); | |
499 | va_end(va); | |
500 | ||
501 | write_mem_lines(file_name, func_name, line_no, lvl, tag, | |
502 | mem_data, mem_len); | |
503 | } |