From ee62510d4e623e5fb4a0cc7d5b450ce18c24e25f Mon Sep 17 00:00:00 2001 From: Felipe Oliveira Carvalho Date: Mon, 28 Apr 2014 19:40:13 -0300 Subject: [PATCH] Macro-based log utility for Neovim This commit introduces 4 macros (for different log levels) that can be used to log messages to $HOME/.nvimlog: - DLOG: log a debug message (e.g. `DLOG("sum(%d, %d): %d", x, y, sum(x, y));`) - ILOG: log some useful information (e.g. `ILOG("Main loop started")`) - WLOG: log a warning (e.g. `WLOG("Command not found: %s", command)`) - ELOG: log an error (e.g. `ELOG("Out of memory. Exiting.")`) All these macros are disabled if `NDEBUG` or `DISABLE_LOG` is defined. This guarantees that a `Release` build won't log anything. `MIN_LOG_LEVEL` can be defined to reduce the verbosity of the log. The log levels are: ``` DEBUG_LOG_LEVEL 0 INFO_LOG_LEVEL 1 WARNING_LOG_LEVEL 2 ERROR_LOG_LEVEL 3 ``` `MIN_LOG_LEVEL` is 0 by default enabling all levels. If `MIN_LOG_LEVEL` is set to 2, for example, only warnings and errors will be logged. That's how the log looks like: ``` DATETIME LOG_LEVEL FUNCTION LINE PID FORMATTED MESSAGE 2014/05/01 23:46:14 [info @ main_loop:582] 44376 - Starting Neovim main loop. 2014/05/01 23:46:31 [info @ main_loop:582] 44400 - Starting Neovim main loop. ``` --- clint-files.txt | 2 + src/log.c | 156 ++++++++++++++++++++++++++++++++++++++++++++++++ src/log.h | 57 ++++++++++++++++++ src/main.c | 2 + src/misc1.h | 4 +- 5 files changed, 220 insertions(+), 1 deletion(-) create mode 100644 src/log.c create mode 100644 src/log.h diff --git a/clint-files.txt b/clint-files.txt index 68c2358f85..76da1f3656 100644 --- a/clint-files.txt +++ b/clint-files.txt @@ -1,5 +1,7 @@ src/indent.c src/indent.h +src/log.c +src/log.h src/os/env.c src/os/event.c src/os/event_defs.h diff --git a/src/log.c b/src/log.c new file mode 100644 index 0000000000..d67851c2d4 --- /dev/null +++ b/src/log.c @@ -0,0 +1,156 @@ +#include +#include +#include +#include +#include +#include +#include +#include + +#include "log.h" +#include "misc1.h" +#include "types.h" +#include "os/os.h" + +#define USR_LOG_FILE "$HOME/.nvimlog" + + +static FILE *open_log_file(void); +static bool do_log_to_file(FILE *log_file, int log_level, + const char *func_name, int line_num, + const char* fmt, ...); +static bool v_do_log_to_file(FILE *log_file, int log_level, + const char *func_name, int line_num, + const char* fmt, va_list args); + +bool do_log(int log_level, const char *func_name, int line_num, + const char* fmt, ...) +{ + FILE *log_file = open_log_file(); + + if (log_file == NULL) { + return false; + } + + va_list args; + va_start(args, fmt); + bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, fmt, + args); + va_end(args); + + if (log_file != stderr && log_file != stdout) { + fclose(log_file); + } + return ret; +} + +/// Open the log file for appending. +/// +/// @return The FILE* specified by the USR_LOG_FILE path or stderr in case of +/// error +static FILE *open_log_file(void) +{ + static bool opening_log_file = false; + + // check if it's a recursive call + if (opening_log_file) { + do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, + "Trying to LOG() recursively! Please fix it."); + return stderr; + } + + // expand USR_LOG_FILE and open the file + FILE *log_file; + opening_log_file = true; + { + static char expanded_log_file_path[MAXPATHL + 1]; + + expand_env((char_u *)USR_LOG_FILE, (char_u *)expanded_log_file_path, + MAXPATHL); + // if the log file path expansion failed then fall back to stderr + if (strcmp(USR_LOG_FILE, expanded_log_file_path) == 0) { + goto open_log_file_error; + } + + log_file = fopen(expanded_log_file_path, "a"); + if (log_file == NULL) { + goto open_log_file_error; + } + } + opening_log_file = false; + + return log_file; + +open_log_file_error: + opening_log_file = false; + + do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, + "Couldn't open USR_LOG_FILE, logging to stderr! This may be " + "caused by attempting to LOG() before initialization " + "functions are called (e.g. init_homedir())."); + return stderr; +} + +static bool do_log_to_file(FILE *log_file, int log_level, + const char *func_name, int line_num, + const char* fmt, ...) +{ + va_list args; + va_start(args, fmt); + bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, fmt, + args); + va_end(args); + + return ret; +} + +static bool v_do_log_to_file(FILE *log_file, int log_level, + const char *func_name, int line_num, + const char* fmt, va_list args) +{ + static const char *log_levels[] = { + [DEBUG_LOG_LEVEL] = "debug", + [INFO_LOG_LEVEL] = "info", + [WARNING_LOG_LEVEL] = "warning", + [ERROR_LOG_LEVEL] = "error" + }; + assert(log_level >= DEBUG_LOG_LEVEL && log_level <= ERROR_LOG_LEVEL); + + // format current timestamp in local time + struct timeval tv; + if (gettimeofday(&tv, NULL) < 0) { + return false; + } +#ifdef UNIX + // localtime() is not thread-safe. POSIX provides localtime_r() as a + // thread-safe version. + struct tm local_time_allocated; + struct tm *local_time = localtime_r(&tv.tv_sec, &local_time_allocated); +#else + // Windows version of localtime() is thread-safe. + // See http://msdn.microsoft.com/en-us/library/bf12f0hc%28VS.80%29.aspx + struct tm *local_time = localtime(&tv.tv_sec); // NOLINT +#endif + char date_time[20]; + if (strftime(date_time, sizeof(date_time), "%Y/%m/%d %H:%M:%S", + local_time) == 0) { + return false; + } + + // print the log message prefixed by the current timestamp and pid + int64_t pid = os_get_pid(); + if (fprintf(log_file, "%s [%s @ %s:%d] %" PRId64 " - ", date_time, + log_levels[log_level], func_name, line_num, pid) < 0) { + return false; + } + if (vfprintf(log_file, fmt, args) < 0) { + return false; + } + fputc('\n', log_file); + if (fflush(log_file) == EOF) { + return false; + } + + return true; +} + diff --git a/src/log.h b/src/log.h new file mode 100644 index 0000000000..45c8fdbfd8 --- /dev/null +++ b/src/log.h @@ -0,0 +1,57 @@ +#ifndef NEOVIM_LOG_H +#define NEOVIM_LOG_H + +#include + +#include "func_attr.h" + +#define DEBUG_LOG_LEVEL 0 +#define INFO_LOG_LEVEL 1 +#define WARNING_LOG_LEVEL 2 +#define ERROR_LOG_LEVEL 3 + +bool do_log(int log_level, const char *func_name, int line_num, + const char* fmt, ...) FUNC_ATTR_UNUSED; + +#define DLOG(...) +#define ILOG(...) +#define WLOG(...) +#define ELOG(...) + +// Logging is disabled if NDEBUG or DISABLE_LOG is defined. +#ifdef NDEBUG +# define DISABLE_LOG +#endif + +// MIN_LOG_LEVEL can be defined during compilation to adjust the desired level +// of logging. DEBUG_LOG_LEVEL is used by default. +#ifndef MIN_LOG_LEVEL +# define MIN_LOG_LEVEL DEBUG_LOG_LEVEL +#endif + +#ifndef DISABLE_LOG + +# if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL +# undef DLOG +# define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# endif + +# if MIN_LOG_LEVEL <= INFO_LOG_LEVEL +# undef ILOG +# define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# endif + +# if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL +# undef WLOG +# define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# endif + +# if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL +# undef ELOG +# define ELOG(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, __VA_ARGS__) +# endif + +#endif + +#endif // NEOVIM_LOG_H + diff --git a/src/main.c b/src/main.c index 105f676bbd..cddd5d15fa 100644 --- a/src/main.c +++ b/src/main.c @@ -33,6 +33,7 @@ #include "misc2.h" #include "crypt.h" #include "garray.h" +#include "log.h" #include "memory.h" #include "move.h" #include "normal.h" @@ -578,6 +579,7 @@ main_loop ( linenr_T conceal_new_cursor_line = 0; int conceal_update_lines = FALSE; + ILOG("Starting Neovim main loop."); clear_oparg(&oa); while (!cmdwin diff --git a/src/misc1.h b/src/misc1.h index a68b9d3b6f..a46b305fae 100644 --- a/src/misc1.h +++ b/src/misc1.h @@ -1,6 +1,8 @@ #ifndef NEOVIM_MISC1_H #define NEOVIM_MISC1_H -/* misc1.c */ + +#include "vim.h" + int open_line(int dir, int flags, int second_line_indent); int get_leader_len(char_u *line, char_u **flags, int backward, int include_space);