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); | |
4d0dd579 | 347 | |
71436ae4 SM |
348 | const char * const errno_msg = g_strerror(errno); |
349 | ||
350 | common_write_init(at, file_name, func_name, line_no, lvl, tag); | |
351 | append_str_to_msg_buf(at, init_msg); | |
352 | append_char_to_msg_buf(at, ':'); | |
353 | append_sp_to_msg_buf(at); | |
354 | append_str_to_msg_buf(at, errno_msg); | |
355 | } | |
356 | ||
357 | void bt_log_write_errno(const char * const file_name, | |
358 | const char * const func_name, const unsigned int line_no, | |
359 | const enum bt_log_level lvl, const char * const tag, | |
360 | const char * const init_msg, const char * const msg) | |
361 | { | |
362 | char *at = msg_buf; | |
363 | ||
364 | common_write_errno_init(&at, file_name, func_name, line_no, lvl, | |
365 | tag, init_msg); | |
366 | append_str_to_msg_buf(&at, msg); | |
367 | common_write_fini(&at); | |
368 | } | |
369 | ||
370 | void bt_log_write_errno_printf(const char * const file_name, | |
371 | const char * const func_name, const unsigned int line_no, | |
372 | const enum bt_log_level lvl, const char * const tag, | |
373 | const char * const init_msg, const char * const fmt, ...) | |
374 | { | |
375 | char *at = msg_buf; | |
376 | int written_len; | |
377 | va_list va; | |
378 | ||
379 | common_write_errno_init(&at, file_name, func_name, line_no, lvl, | |
380 | tag, init_msg); | |
381 | va_start(va, fmt); | |
382 | written_len = vsnprintf(at, avail_msg_buf_bytes(at) - 16, fmt, va); | |
383 | va_end(va); | |
384 | if (written_len > 0) { | |
385 | at += (size_t) written_len; | |
386 | } | |
387 | ||
388 | common_write_fini(&at); | |
389 | } | |
390 | ||
391 | /* | |
392 | * Logs `mem_len` bytes of `mem_data` on a single line. | |
393 | */ | |
394 | static | |
395 | void write_mem_line(const char * const file_name, const char * const func_name, | |
396 | const unsigned int line_no, const enum bt_log_level lvl, | |
397 | const char * const tag, const uint8_t * const mem_data, | |
398 | const size_t mem_len, const size_t max_mem_line_len) | |
399 | { | |
400 | static const char * const hex_chars = "0123456789abcdef"; | |
401 | char *at = msg_buf; | |
402 | size_t i; | |
403 | ||
404 | common_write_init(&at, file_name, func_name, line_no, lvl, tag); | |
405 | ||
406 | /* Write hexadecimal representation */ | |
407 | for (i = 0; i < mem_len; i++) { | |
408 | const uint8_t byte = mem_data[i]; | |
409 | ||
410 | /* Write nibble */ | |
411 | append_char_to_msg_buf(&at, hex_chars[byte >> 4]); | |
412 | append_char_to_msg_buf(&at, hex_chars[byte & 0xf]); | |
413 | ||
414 | /* Add a space */ | |
415 | append_sp_to_msg_buf(&at); | |
416 | } | |
417 | ||
418 | /* Insert spaces to align the following ASCII representation */ | |
419 | for (i = 0; i < max_mem_line_len - mem_len; i++) { | |
420 | append_sp_to_msg_buf(&at); | |
421 | append_sp_to_msg_buf(&at); | |
422 | append_sp_to_msg_buf(&at); | |
423 | } | |
424 | ||
425 | /* Insert a vertical line between the representations */ | |
426 | append_str_to_msg_buf(&at, "| "); | |
427 | ||
428 | /* Write the ASCII representation */ | |
429 | for (i = 0; i < mem_len; i++) { | |
430 | const uint8_t byte = mem_data[i]; | |
431 | ||
432 | if (isprint(byte)) { | |
433 | append_char_to_msg_buf(&at, (char) byte); | |
434 | } else { | |
435 | /* Non-printable character */ | |
436 | append_char_to_msg_buf(&at, '.'); | |
437 | } | |
438 | } | |
439 | ||
440 | common_write_fini(&at); | |
441 | } | |
442 | ||
443 | /* | |
444 | * Logs `mem_len` bytes of `mem_data` on one or more lines. | |
445 | */ | |
446 | static | |
447 | void write_mem_lines(const char * const file_name, const char * const func_name, | |
448 | const unsigned int line_no, const enum bt_log_level lvl, | |
449 | const char * const tag, const uint8_t * const mem_data, | |
450 | const size_t mem_len) | |
451 | { | |
452 | const uint8_t *mem_at = mem_data; | |
453 | size_t rem_mem_len = mem_len; | |
454 | ||
455 | if (!mem_data || mem_len == 0) { | |
456 | /* Nothing to write */ | |
457 | goto end; | |
458 | } | |
459 | ||
460 | while (rem_mem_len > 0) { | |
461 | static const size_t max_mem_line_len = 16; | |
462 | ||
463 | /* Number of bytes to write on this line */ | |
464 | const size_t mem_line_len = rem_mem_len > max_mem_line_len ? | |
465 | max_mem_line_len : rem_mem_len; | |
466 | ||
467 | /* Log those bytes */ | |
468 | write_mem_line(file_name, func_name, line_no, lvl, tag, | |
469 | mem_at, mem_line_len, max_mem_line_len); | |
470 | ||
471 | /* Adjust for next iteration */ | |
472 | rem_mem_len -= mem_line_len; | |
473 | mem_at += mem_line_len; | |
474 | } | |
475 | ||
476 | end: | |
477 | return; | |
478 | } | |
479 | ||
480 | void bt_log_write_mem(const char * const file_name, const char * const func_name, | |
481 | const unsigned int line_no, const enum bt_log_level lvl, | |
482 | const char * const tag, const void * const mem_data, | |
483 | const size_t mem_len, const char * const msg) | |
484 | { | |
485 | bt_log_write(file_name, func_name, line_no, lvl, tag, msg); | |
486 | write_mem_lines(file_name, func_name, line_no, lvl, tag, | |
487 | mem_data, mem_len); | |
488 | } | |
489 | ||
490 | void bt_log_write_mem_printf(const char * const file_name, | |
491 | const char * const func_name, const unsigned int line_no, | |
492 | const enum bt_log_level lvl, const char * const tag, | |
493 | const void * const mem_data, const size_t mem_len, | |
494 | const char * const fmt, ...) | |
495 | { | |
496 | va_list va; | |
497 | ||
498 | va_start(va, fmt); | |
499 | write_vprintf(file_name, func_name, line_no, lvl, tag, fmt, va); | |
500 | va_end(va); | |
501 | ||
502 | write_mem_lines(file_name, func_name, line_no, lvl, tag, | |
503 | mem_data, mem_len); | |
504 | } |