neovim

Neovim text editor
git clone https://git.dasho.dev/neovim.git
Log | Files | Refs | README

log.c (10473B)

      1 //
      2 // Log module
      3 //
      4 // How Linux printk() handles recursion, buffering, etc:
      5 // https://lwn.net/Articles/780556/
      6 //
      7 
      8 #include <assert.h>
      9 #include <errno.h>
     10 #include <inttypes.h>
     11 #include <stdarg.h>
     12 #include <stdbool.h>
     13 #include <stdio.h>
     14 #include <stdlib.h>
     15 #include <string.h>
     16 #include <time.h>
     17 #include <uv.h>
     18 
     19 #include "auto/config.h"
     20 #include "nvim/ascii_defs.h"
     21 #include "nvim/eval/vars.h"
     22 #include "nvim/globals.h"
     23 #include "nvim/log.h"
     24 #include "nvim/memory.h"
     25 #include "nvim/message.h"
     26 #include "nvim/os/fs.h"
     27 #include "nvim/os/os.h"
     28 #include "nvim/os/os_defs.h"
     29 #include "nvim/os/stdpaths_defs.h"
     30 #include "nvim/os/time.h"
     31 #include "nvim/path.h"
     32 #include "nvim/ui_client.h"
     33 
     34 /// Cached location of the expanded log file path decided by log_path_init().
     35 static char log_file_path[MAXPATHL + 1] = { 0 };
     36 
     37 static bool did_log_init = false;
     38 static uv_mutex_t mutex;
     39 
     40 #include "log.c.generated.h"
     41 
     42 #ifdef HAVE_EXECINFO_BACKTRACE
     43 # include <execinfo.h>
     44 #endif
     45 
     46 static bool log_try_create(char *fname)
     47 {
     48  if (fname == NULL || fname[0] == NUL) {
     49    return false;
     50  }
     51  FILE *log_file = fopen(fname, "a");
     52  if (log_file == NULL) {
     53    return false;
     54  }
     55  fclose(log_file);
     56  return true;
     57 }
     58 
     59 /// Initializes the log file path and sets $NVIM_LOG_FILE if empty.
     60 ///
     61 /// Tries $NVIM_LOG_FILE, or falls back to $XDG_STATE_HOME/nvim/nvim.log. Failed
     62 /// initialization indicates either a bug in expand_env() or both $NVIM_LOG_FILE
     63 /// and $HOME environment variables are undefined.
     64 static void log_path_init(void)
     65 {
     66  size_t size = sizeof(log_file_path);
     67  expand_env("$" ENV_LOGFILE, log_file_path, (int)size - 1);
     68  if (strequal("$" ENV_LOGFILE, log_file_path)
     69      || log_file_path[0] == NUL
     70      || os_isdir(log_file_path)
     71      || !log_try_create(log_file_path)) {
     72    // Make $XDG_STATE_HOME if it does not exist.
     73    char *loghome = get_xdg_home(kXDGStateHome);
     74    char *failed_dir = NULL;
     75    bool log_dir_failure = false;
     76    if (!os_isdir(loghome)) {
     77      log_dir_failure = (os_mkdir_recurse(loghome, 0700, &failed_dir, NULL) != 0);
     78    }
     79    XFREE_CLEAR(loghome);
     80    // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default.
     81    char *defaultpath = stdpaths_user_state_subpath("nvim.log", 0, true);
     82    size_t len = xstrlcpy(log_file_path, defaultpath, size);
     83    xfree(defaultpath);
     84    // Fall back to $CWD/nvim.log
     85    if (len >= size || !log_try_create(log_file_path)) {
     86      len = xstrlcpy(log_file_path, "nvim.log", size);
     87    }
     88    // Fall back to stderr
     89    if (len >= size || !log_try_create(log_file_path)) {
     90      log_file_path[0] = NUL;
     91      return;
     92    }
     93    os_setenv(ENV_LOGFILE, log_file_path, true);
     94    if (log_dir_failure) {
     95      WLOG("Failed to create directory %s for writing logs: %s",
     96           failed_dir, os_strerror(log_dir_failure));
     97    }
     98    XFREE_CLEAR(failed_dir);
     99  }
    100 }
    101 
    102 void log_init(void)
    103 {
    104  uv_mutex_init_recursive(&mutex);
    105  // AFTER init_homedir ("~", XDG) and set_init_1 (env vars). 22b52dd462e5 #11501
    106  log_path_init();
    107  did_log_init = true;
    108 }
    109 
    110 void log_lock(void)
    111 {
    112  uv_mutex_lock(&mutex);
    113 }
    114 
    115 void log_unlock(void)
    116 {
    117  uv_mutex_unlock(&mutex);
    118 }
    119 
    120 /// Logs a message to $NVIM_LOG_FILE.
    121 ///
    122 /// @param log_level  Log level (see log.h)
    123 /// @param context    Description of a shared context or subsystem
    124 /// @param func_name  Function name, or NULL
    125 /// @param line_num   Source line number, or -1
    126 /// @param eol        Append linefeed "\n"
    127 /// @param fmt        printf-style format string
    128 ///
    129 /// @return true if log was emitted normally, false if failed or recursive
    130 bool logmsg(int log_level, const char *context, const char *func_name, int line_num, bool eol,
    131            const char *fmt, ...)
    132  FUNC_ATTR_PRINTF(6, 7)
    133 {
    134  static bool recursive = false;
    135  static bool did_msg = false;  // Showed recursion message?
    136  if (!did_log_init) {
    137    g_stats.log_skip++;
    138    // set_init_1 may try logging before we are ready. 6f27f5ef91b3 #10183
    139    return false;
    140  }
    141 
    142 #ifndef NVIM_LOG_DEBUG
    143  // This should rarely happen (callsites are compiled out), but to be sure.
    144  // TODO(bfredl): allow log levels to be configured at runtime
    145  if (log_level < LOGLVL_WRN) {
    146    return false;
    147  }
    148 #endif
    149 
    150 #ifdef EXITFREE
    151  // Logging after we've already started freeing all our memory will only cause
    152  // pain.  We need access to VV_PROGPATH, homedir, etc.
    153  if (entered_free_all_mem) {
    154    fprintf(stderr, "FATAL: error in free_all_mem\n %s %s %d: ", context, func_name, line_num);
    155    va_list args;
    156    va_start(args, fmt);
    157    vfprintf(stderr, fmt, args);
    158    va_end(args);
    159    if (eol) {
    160      fprintf(stderr, "\n");
    161    }
    162    abort();
    163  }
    164 #endif
    165 
    166  log_lock();
    167  if (recursive) {
    168    if (!did_msg) {
    169      did_msg = true;
    170      msg_schedule_semsg("E5430: %s:%d: recursive log!", func_name ? func_name : context, line_num);
    171    }
    172    g_stats.log_skip++;
    173    log_unlock();
    174    return false;
    175  }
    176  recursive = true;
    177  bool ret = false;
    178  FILE *log_file = open_log_file();
    179 
    180  va_list args;
    181  va_start(args, fmt);
    182  ret = v_do_log_to_file(log_file, log_level, context, func_name, line_num,
    183                         eol, fmt, args);
    184  va_end(args);
    185 
    186  if (log_file != stderr && log_file != stdout) {
    187    fclose(log_file);
    188  }
    189 
    190  recursive = false;
    191  log_unlock();
    192  return ret;
    193 }
    194 
    195 void log_uv_handles(void *loop)
    196 {
    197  uv_loop_t *l = loop;
    198  log_lock();
    199  FILE *log_file = open_log_file();
    200 
    201  uv_print_all_handles(l, log_file);
    202 
    203  if (log_file != stderr && log_file != stdout) {
    204    fclose(log_file);
    205  }
    206 
    207  log_unlock();
    208 }
    209 
    210 /// Open the log file for appending.
    211 ///
    212 /// @return Log file, or stderr on failure
    213 FILE *open_log_file(void)
    214 {
    215  errno = 0;
    216  if (log_file_path[0]) {
    217    FILE *f = fopen(log_file_path, "a");
    218    if (f != NULL) {
    219      return f;
    220    }
    221  }
    222 
    223  // May happen if:
    224  //  - fopen() failed
    225  //  - LOG() is called before log_init()
    226  //  - Directory does not exist
    227  //  - File is not writable
    228  do_log_to_file(stderr, LOGLVL_ERR, NULL, __func__, __LINE__, true,
    229                 "failed to open $" ENV_LOGFILE " (%s): %s",
    230                 strerror(errno), log_file_path);
    231  return stderr;
    232 }
    233 
    234 #ifdef HAVE_EXECINFO_BACKTRACE
    235 void log_callstack_to_file(FILE *log_file, const char *const func_name, const int line_num)
    236 {
    237  void *trace[100];
    238  int trace_size = backtrace(trace, ARRAY_SIZE(trace));
    239 
    240  char exepath[MAXPATHL] = { 0 };
    241  size_t exepathlen = MAXPATHL;
    242  if (os_exepath(exepath, &exepathlen) != 0) {
    243    abort();
    244  }
    245  assert(24 + exepathlen < IOSIZE);  // Must fit in `cmdbuf` below.
    246 
    247  char cmdbuf[IOSIZE + (20 * ARRAY_SIZE(trace)) + MAXPATHL];
    248  snprintf(cmdbuf, sizeof(cmdbuf), "addr2line -e %s -f -p", exepath);
    249  for (int i = 1; i < trace_size; i++) {
    250    char buf[20];  // 64-bit pointer 0xNNNNNNNNNNNNNNNN with leading space.
    251    snprintf(buf, sizeof(buf), " %p", trace[i]);
    252    xstrlcat(cmdbuf, buf, sizeof(cmdbuf));
    253  }
    254  // Now we have a command string like:
    255  //    addr2line -e /path/to/exe -f -p 0x123 0x456 ...
    256 
    257  do_log_to_file(log_file, LOGLVL_DBG, NULL, func_name, line_num, true, "trace:");
    258  FILE *fp = popen(cmdbuf, "r");
    259  assert(fp);
    260  char linebuf[IOSIZE];
    261  while (fgets(linebuf, sizeof(linebuf) - 1, fp) != NULL) {
    262    fprintf(log_file, "  %s", linebuf);
    263  }
    264  pclose(fp);
    265 
    266  if (log_file != stderr && log_file != stdout) {
    267    fclose(log_file);
    268  }
    269 }
    270 
    271 void log_callstack(const char *const func_name, const int line_num)
    272 {
    273  log_lock();
    274  FILE *log_file = open_log_file();
    275  log_callstack_to_file(log_file, func_name, line_num);
    276  log_unlock();
    277 }
    278 #endif
    279 
    280 static bool do_log_to_file(FILE *log_file, int log_level, const char *context,
    281                           const char *func_name, int line_num, bool eol, const char *fmt, ...)
    282  FUNC_ATTR_PRINTF(7, 8)
    283 {
    284  va_list args;
    285  va_start(args, fmt);
    286  bool ret = v_do_log_to_file(log_file, log_level, context, func_name,
    287                              line_num, eol, fmt, args);
    288  va_end(args);
    289 
    290  return ret;
    291 }
    292 
    293 static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
    294                             const char *func_name, int line_num, bool eol, const char *fmt,
    295                             va_list args)
    296  FUNC_ATTR_PRINTF(7, 0)
    297 {
    298  // Name of the Nvim instance that produced the log.
    299  static char name[32] = { 0 };
    300 
    301  static const char *log_levels[] = {
    302    [LOGLVL_DBG] = "DBG",
    303    [LOGLVL_INF] = "INF",
    304    [LOGLVL_WRN] = "WRN",
    305    [LOGLVL_ERR] = "ERR",
    306  };
    307  assert(log_level >= LOGLVL_DBG && log_level <= LOGLVL_ERR);
    308 
    309  // Format the timestamp.
    310  struct tm local_time;
    311  if (os_localtime(&local_time) == NULL) {
    312    return false;
    313  }
    314  char date_time[20];
    315  if (strftime(date_time, sizeof(date_time), "%Y-%m-%dT%H:%M:%S", &local_time) == 0) {
    316    return false;
    317  }
    318 
    319  int millis = 0;
    320  uv_timeval64_t curtime;
    321  if (uv_gettimeofday(&curtime) == 0) {
    322    millis = (int)curtime.tv_usec / 1000;
    323  }
    324 
    325  bool ui = !!ui_client_channel_id;  // Running as a UI client (--remote-ui).
    326 
    327  // Regenerate the name when:
    328  // - UI client (to ensure "ui" is in the name)
    329  // - not set yet
    330  // - no v:servername yet
    331  bool regen = ui || name[0] == NUL || name[0] == '?';
    332 
    333  // Get a name for this Nvim instance.
    334  // TODO(justinmk): expose this as v:name ?
    335  if (regen) {
    336    char parent_buf[MAXPATHL];
    337    // Parent servername ($NVIM).
    338    const char *parent = path_tail(os_getenv_buf(ENV_NVIM, parent_buf, sizeof(parent_buf)));
    339    // Servername. Empty until starting=false.
    340    const char *serv = path_tail(get_vim_var_str(VV_SEND_SERVER));
    341    if (parent[0] != NUL) {
    342      snprintf(name, sizeof(name), ui ? "ui/c/%s" : "c/%s", parent);  // "c/" = child of $NVIM.
    343    } else if (serv[0] != NUL) {
    344      snprintf(name, sizeof(name), ui ? "ui/%s" : "%s", serv);
    345    } else {
    346      int64_t pid = os_get_pid();
    347      snprintf(name, sizeof(name), "%s.%-5" PRId64, ui ? "ui" : "?", pid);
    348    }
    349  }
    350 
    351  // Print the log message.
    352  int rv = (line_num == -1 || func_name == NULL)
    353           ? fprintf(log_file, "%s %s.%03d %-10s %s",
    354                     log_levels[log_level], date_time, millis, name,
    355                     (context == NULL ? "?:" : context))
    356           : fprintf(log_file, "%s %s.%03d %-10s %s%s:%d: ",
    357                     log_levels[log_level], date_time, millis, name,
    358                     (context == NULL ? "" : context),
    359                     func_name, line_num);
    360 
    361  if (rv < 0) {
    362    return false;
    363  }
    364  if (vfprintf(log_file, fmt, args) < 0) {
    365    return false;
    366  }
    367  if (eol) {
    368    fputc('\n', log_file);
    369  }
    370  if (fflush(log_file) == EOF) {
    371    return false;
    372  }
    373 
    374  return true;
    375 }