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 #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(&ltid);
 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 }