// This is an open source non-commercial project. Dear PVS-Studio, please check // it. PVS-Studio Static Code Analyzer for C, C++ and C#: http://www.viva64.com // // Log module // // How Linux printk() handles recursion, buffering, etc: // https://lwn.net/Articles/780556/ // #include #include #include #include #include #include #include "auto/config.h" #include "nvim/log.h" #include "nvim/os/os.h" #include "nvim/os/time.h" #include "nvim/types.h" #define LOG_FILE_ENV "NVIM_LOG_FILE" /// Cached location of the expanded log file path decided by log_path_init(). static char log_file_path[MAXPATHL + 1] = { 0 }; static uv_mutex_t mutex; #ifdef INCLUDE_GENERATED_DECLARATIONS # include "log.c.generated.h" #endif #ifdef HAVE_EXECINFO_BACKTRACE # include #endif static bool log_try_create(char *fname) { if (fname == NULL || fname[0] == '\0') { return false; } FILE *log_file = fopen(fname, "a"); if (log_file == NULL) { return false; } fclose(log_file); return true; } /// Initializes path to log file. Sets $NVIM_LOG_FILE if empty. /// /// Tries $NVIM_LOG_FILE, or falls back to $XDG_CACHE_HOME/nvim/log. Path to log /// file is cached, so only the first call has effect, unless first call was not /// successful. Failed initialization indicates either a bug in expand_env() /// or both $NVIM_LOG_FILE and $HOME environment variables are undefined. /// /// @return true if path was initialized, false otherwise. static bool log_path_init(void) { if (log_file_path[0]) { return true; } size_t size = sizeof(log_file_path); expand_env((char_u *)"$" LOG_FILE_ENV, (char_u *)log_file_path, (int)size - 1); if (strequal("$" LOG_FILE_ENV, log_file_path) || log_file_path[0] == '\0' || os_isdir((char_u *)log_file_path) || !log_try_create(log_file_path)) { // Make kXDGCacheHome if it does not exist. char *cachehome = get_xdg_home(kXDGCacheHome); char *failed_dir = NULL; bool log_dir_failure = false; if (!os_isdir((char_u *)cachehome)) { log_dir_failure = (os_mkdir_recurse(cachehome, 0700, &failed_dir) != 0); } XFREE_CLEAR(cachehome); // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default. char *defaultpath = stdpaths_user_cache_subpath("log"); size_t len = xstrlcpy(log_file_path, defaultpath, size); xfree(defaultpath); // Fall back to .nvimlog if (len >= size || !log_try_create(log_file_path)) { len = xstrlcpy(log_file_path, ".nvimlog", size); } // Fall back to stderr if (len >= size || !log_try_create(log_file_path)) { log_file_path[0] = '\0'; return false; } os_setenv(LOG_FILE_ENV, log_file_path, true); if (log_dir_failure) { WLOG("Failed to create directory %s for writing logs: %s", failed_dir, os_strerror(log_dir_failure)); } XFREE_CLEAR(failed_dir); } return true; } void log_init(void) { uv_mutex_init(&mutex); log_path_init(); } void log_lock(void) { uv_mutex_lock(&mutex); } void log_unlock(void) { uv_mutex_unlock(&mutex); } /// Logs a message to $NVIM_LOG_FILE. /// /// @param log_level Log level (see log.h) /// @param context Description of a shared context or subsystem /// @param func_name Function name, or NULL /// @param line_num Source line number, or -1 /// @param eol Append linefeed "\n" /// @param fmt printf-style format string bool logmsg(int log_level, const char *context, const char *func_name, int line_num, bool eol, const char *fmt, ...) FUNC_ATTR_UNUSED FUNC_ATTR_PRINTF(6, 7) { if (log_level < MIN_LOG_LEVEL) { return false; } #ifdef EXITFREE // Logging after we've already started freeing all our memory will only cause // pain. We need access to VV_PROGPATH, homedir, etc. assert(!entered_free_all_mem); #endif log_lock(); bool ret = false; FILE *log_file = open_log_file(); if (log_file == NULL) { goto end; } va_list args; va_start(args, fmt); ret = v_do_log_to_file(log_file, log_level, context, func_name, line_num, eol, fmt, args); va_end(args); if (log_file != stderr && log_file != stdout) { fclose(log_file); } end: log_unlock(); return ret; } void log_uv_handles(void *loop) { uv_loop_t *l = loop; log_lock(); FILE *log_file = open_log_file(); if (log_file == NULL) { goto end; } uv_print_all_handles(l, log_file); if (log_file != stderr && log_file != stdout) { fclose(log_file); } end: log_unlock(); } /// Open the log file for appending. /// /// @return FILE* decided by log_path_init() or stderr in case of error FILE *open_log_file(void) { static bool opening_log_file = false; // Disallow recursion. (This only matters for log_path_init; for logmsg and // friends we use a mutex: log_lock). if (opening_log_file) { do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true, "Cannot LOG() recursively."); return stderr; } FILE *log_file = NULL; opening_log_file = true; if (log_path_init()) { log_file = fopen(log_file_path, "a"); } opening_log_file = false; if (log_file != NULL) { return log_file; } // May happen if: // - LOG() is called before early_init() // - Directory does not exist // - File is not writable do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true, "Logging to stderr, failed to open $" LOG_FILE_ENV ": %s", log_file_path); return stderr; } #ifdef HAVE_EXECINFO_BACKTRACE void log_callstack_to_file(FILE *log_file, const char *const func_name, const int line_num) { void *trace[100]; int trace_size = backtrace(trace, ARRAY_SIZE(trace)); char exepath[MAXPATHL] = { 0 }; size_t exepathlen = MAXPATHL; if (os_exepath(exepath, &exepathlen) != 0) { abort(); } assert(24 + exepathlen < IOSIZE); // Must fit in `cmdbuf` below. char cmdbuf[IOSIZE + (20 * ARRAY_SIZE(trace)) + MAXPATHL]; snprintf(cmdbuf, sizeof(cmdbuf), "addr2line -e %s -f -p", exepath); for (int i = 1; i < trace_size; i++) { char buf[20]; // 64-bit pointer 0xNNNNNNNNNNNNNNNN with leading space. snprintf(buf, sizeof(buf), " %p", trace[i]); xstrlcat(cmdbuf, buf, sizeof(cmdbuf)); } // Now we have a command string like: // addr2line -e /path/to/exe -f -p 0x123 0x456 ... do_log_to_file(log_file, DEBUG_LOG_LEVEL, NULL, func_name, line_num, true, "trace:"); FILE *fp = popen(cmdbuf, "r"); char linebuf[IOSIZE]; while (fgets(linebuf, sizeof(linebuf) - 1, fp) != NULL) { fprintf(log_file, " %s", linebuf); } pclose(fp); if (log_file != stderr && log_file != stdout) { fclose(log_file); } } void log_callstack(const char *const func_name, const int line_num) { log_lock(); FILE *log_file = open_log_file(); if (log_file == NULL) { goto end; } log_callstack_to_file(log_file, func_name, line_num); end: log_unlock(); } #endif static bool do_log_to_file(FILE *log_file, int log_level, const char *context, const char *func_name, int line_num, bool eol, const char *fmt, ...) FUNC_ATTR_PRINTF(7, 8) { va_list args; va_start(args, fmt); bool ret = v_do_log_to_file(log_file, log_level, context, func_name, line_num, eol, fmt, args); va_end(args); return ret; } static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context, const char *func_name, int line_num, bool eol, const char *fmt, va_list args) FUNC_ATTR_PRINTF(7, 0) { static const char *log_levels[] = { [DEBUG_LOG_LEVEL] = "DEBUG", [INFO_LOG_LEVEL] = "INFO ", [WARN_LOG_LEVEL] = "WARN ", [ERROR_LOG_LEVEL] = "ERROR", }; assert(log_level >= DEBUG_LOG_LEVEL && log_level <= ERROR_LOG_LEVEL); // Format the timestamp. struct tm local_time; if (os_localtime(&local_time) == NULL) { return false; } char date_time[20]; if (strftime(date_time, sizeof(date_time), "%Y-%m-%dT%H:%M:%S", &local_time) == 0) { return false; } int millis = 0; uv_timeval64_t curtime; if (uv_gettimeofday(&curtime) == 0) { millis = (int)curtime.tv_usec / 1000; } // Print the log message. int64_t pid = os_get_pid(); int rv = (line_num == -1 || func_name == NULL) ? fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s", log_levels[log_level], date_time, millis, pid, (context == NULL ? "?:" : context)) : fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s%s:%d: ", log_levels[log_level], date_time, millis, pid, (context == NULL ? "" : context), func_name, line_num); if (rv < 0) { return false; } if (vfprintf(log_file, fmt, args) < 0) { return false; } if (eol) { fputc('\n', log_file); } if (fflush(log_file) == EOF) { return false; } return true; }