| 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 | |
| 39 | #ifdef __FreeBSD__ |
| 40 | # include <sys/thr.h> |
| 41 | #endif |
| 42 | |
| 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 | } |
| 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 | } |
| 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 | |
| 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 | } |