src/logging/log-api.c

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