1// This is an open source non-commercial project. Dear PVS-Studio, please check
2// it. PVS-Studio Static Code Analyzer for C, C++ and C#: http://www.viva64.com
3
4//
5// Log module
6//
7// How Linux printk() handles recursion, buffering, etc:
8// https://lwn.net/Articles/780556/
9//
10
11#include <assert.h>
12#include <inttypes.h>
13#include <stdarg.h>
14#include <stdbool.h>
15#include <stdio.h>
16#if !defined(WIN32)
17# include <sys/time.h> // for gettimeofday()
18#endif
19#include <uv.h>
20
21#include "auto/config.h"
22#include "nvim/log.h"
23#include "nvim/types.h"
24#include "nvim/os/os.h"
25#include "nvim/os/time.h"
26
27#define LOG_FILE_ENV "NVIM_LOG_FILE"
28
29/// Cached location of the expanded log file path decided by log_path_init().
30static char log_file_path[MAXPATHL + 1] = { 0 };
31
32static uv_mutex_t mutex;
33
34#ifdef INCLUDE_GENERATED_DECLARATIONS
35# include "log.c.generated.h"
36#endif
37
38#ifdef HAVE_EXECINFO_BACKTRACE
39# include <execinfo.h>
40#endif
41
42static bool log_try_create(char *fname)
43{
44 if (fname == NULL || fname[0] == '\0') {
45 return false;
46 }
47 FILE *log_file = fopen(fname, "a");
48 if (log_file == NULL) {
49 return false;
50 }
51 fclose(log_file);
52 return true;
53}
54
55/// Initializes path to log file. Sets $NVIM_LOG_FILE if empty.
56///
57/// Tries $NVIM_LOG_FILE, or falls back to $XDG_DATA_HOME/nvim/log. Path to log
58/// file is cached, so only the first call has effect, unless first call was not
59/// successful. Failed initialization indicates either a bug in expand_env()
60/// or both $NVIM_LOG_FILE and $HOME environment variables are undefined.
61///
62/// @return true if path was initialized, false otherwise.
63static bool log_path_init(void)
64{
65 if (log_file_path[0]) {
66 return true;
67 }
68 size_t size = sizeof(log_file_path);
69 expand_env((char_u *)"$" LOG_FILE_ENV, (char_u *)log_file_path,
70 (int)size - 1);
71 if (strequal("$" LOG_FILE_ENV, log_file_path)
72 || log_file_path[0] == '\0'
73 || os_isdir((char_u *)log_file_path)
74 || !log_try_create(log_file_path)) {
75 // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default.
76 char *defaultpath = stdpaths_user_data_subpath("log", 0, true);
77 size_t len = xstrlcpy(log_file_path, defaultpath, size);
78 xfree(defaultpath);
79 // Fall back to .nvimlog
80 if (len >= size || !log_try_create(log_file_path)) {
81 len = xstrlcpy(log_file_path, ".nvimlog", size);
82 }
83 // Fall back to stderr
84 if (len >= size || !log_try_create(log_file_path)) {
85 log_file_path[0] = '\0';
86 return false;
87 }
88 os_setenv(LOG_FILE_ENV, log_file_path, true);
89 }
90 return true;
91}
92
93void log_init(void)
94{
95 uv_mutex_init(&mutex);
96}
97
98void log_lock(void)
99{
100 uv_mutex_lock(&mutex);
101}
102
103void log_unlock(void)
104{
105 uv_mutex_unlock(&mutex);
106}
107
108/// Logs a message to $NVIM_LOG_FILE.
109///
110/// @param log_level Log level (see log.h)
111/// @param context Description of a shared context or subsystem
112/// @param func_name Function name, or NULL
113/// @param line_num Source line number, or -1
114/// @param eol Append linefeed "\n"
115/// @param fmt printf-style format string
116bool logmsg(int log_level, const char *context, const char *func_name,
117 int line_num, bool eol, const char *fmt, ...)
118 FUNC_ATTR_UNUSED FUNC_ATTR_PRINTF(6, 7)
119{
120 if (log_level < MIN_LOG_LEVEL) {
121 return false;
122 }
123
124#ifdef EXITFREE
125 // Logging after we've already started freeing all our memory will only cause
126 // pain. We need access to VV_PROGPATH, homedir, etc.
127 assert(!entered_free_all_mem);
128#endif
129
130 log_lock();
131 bool ret = false;
132 FILE *log_file = open_log_file();
133
134 if (log_file == NULL) {
135 goto end;
136 }
137
138 va_list args;
139 va_start(args, fmt);
140 ret = v_do_log_to_file(log_file, log_level, context, func_name, line_num,
141 eol, fmt, args);
142 va_end(args);
143
144 if (log_file != stderr && log_file != stdout) {
145 fclose(log_file);
146 }
147end:
148 log_unlock();
149 return ret;
150}
151
152void log_uv_handles(void *loop)
153{
154 uv_loop_t *l = loop;
155 log_lock();
156 FILE *log_file = open_log_file();
157
158 if (log_file == NULL) {
159 goto end;
160 }
161
162 uv_print_all_handles(l, log_file);
163
164 if (log_file != stderr && log_file != stdout) {
165 fclose(log_file);
166 }
167end:
168 log_unlock();
169}
170
171/// Open the log file for appending.
172///
173/// @return FILE* decided by log_path_init() or stderr in case of error
174FILE *open_log_file(void)
175{
176 static bool opening_log_file = false;
177 // Disallow recursion. (This only matters for log_path_init; for logmsg and
178 // friends we use a mutex: log_lock).
179 if (opening_log_file) {
180 do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true,
181 "Cannot LOG() recursively.");
182 return stderr;
183 }
184
185 FILE *log_file = NULL;
186 opening_log_file = true;
187 if (log_path_init()) {
188 log_file = fopen(log_file_path, "a");
189 }
190 opening_log_file = false;
191
192 if (log_file != NULL) {
193 return log_file;
194 }
195
196 // May happen if:
197 // - LOG() is called before early_init()
198 // - Directory does not exist
199 // - File is not writable
200 do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true,
201 "Logging to stderr, failed to open $" LOG_FILE_ENV ": %s",
202 log_file_path);
203 return stderr;
204}
205
206#ifdef HAVE_EXECINFO_BACKTRACE
207void log_callstack_to_file(FILE *log_file, const char *const func_name,
208 const int line_num)
209{
210 void *trace[100];
211 int trace_size = backtrace(trace, ARRAY_SIZE(trace));
212
213 char exepath[MAXPATHL] = { 0 };
214 size_t exepathlen = MAXPATHL;
215 if (os_exepath(exepath, &exepathlen) != 0) {
216 abort();
217 }
218 assert(24 + exepathlen < IOSIZE); // Must fit in `cmdbuf` below.
219
220 char cmdbuf[IOSIZE + (20 * ARRAY_SIZE(trace)) + MAXPATHL];
221 snprintf(cmdbuf, sizeof(cmdbuf), "addr2line -e %s -f -p", exepath);
222 for (int i = 1; i < trace_size; i++) {
223 char buf[20]; // 64-bit pointer 0xNNNNNNNNNNNNNNNN with leading space.
224 snprintf(buf, sizeof(buf), " %p", trace[i]);
225 xstrlcat(cmdbuf, buf, sizeof(cmdbuf));
226 }
227 // Now we have a command string like:
228 // addr2line -e /path/to/exe -f -p 0x123 0x456 ...
229
230 do_log_to_file(log_file, DEBUG_LOG_LEVEL, NULL, func_name, line_num, true,
231 "trace:");
232 FILE *fp = popen(cmdbuf, "r");
233 char linebuf[IOSIZE];
234 while (fgets(linebuf, sizeof(linebuf) - 1, fp) != NULL) {
235 fprintf(log_file, " %s", linebuf);
236 }
237 pclose(fp);
238
239 if (log_file != stderr && log_file != stdout) {
240 fclose(log_file);
241 }
242}
243
244void log_callstack(const char *const func_name, const int line_num)
245{
246 log_lock();
247 FILE *log_file = open_log_file();
248 if (log_file == NULL) {
249 goto end;
250 }
251
252 log_callstack_to_file(log_file, func_name, line_num);
253
254end:
255 log_unlock();
256}
257#endif
258
259static bool do_log_to_file(FILE *log_file, int log_level, const char *context,
260 const char *func_name, int line_num, bool eol,
261 const char *fmt, ...)
262 FUNC_ATTR_PRINTF(7, 8)
263{
264 va_list args;
265 va_start(args, fmt);
266 bool ret = v_do_log_to_file(log_file, log_level, context, func_name,
267 line_num, eol, fmt, args);
268 va_end(args);
269
270 return ret;
271}
272
273static bool v_do_log_to_file(FILE *log_file, int log_level,
274 const char *context, const char *func_name,
275 int line_num, bool eol, const char *fmt,
276 va_list args)
277{
278 static const char *log_levels[] = {
279 [DEBUG_LOG_LEVEL] = "DEBUG",
280 [INFO_LOG_LEVEL] = "INFO ",
281 [WARN_LOG_LEVEL] = "WARN ",
282 [ERROR_LOG_LEVEL] = "ERROR",
283 };
284 assert(log_level >= DEBUG_LOG_LEVEL && log_level <= ERROR_LOG_LEVEL);
285
286 // Format the timestamp.
287 struct tm local_time;
288 if (os_localtime(&local_time) == NULL) {
289 return false;
290 }
291 char date_time[20];
292 if (strftime(date_time, sizeof(date_time), "%Y-%m-%dT%H:%M:%S",
293 &local_time) == 0) {
294 return false;
295 }
296
297 int millis = 0;
298#if !defined(WIN32)
299 struct timeval curtime;
300 if (gettimeofday(&curtime, NULL) == 0) {
301 millis = (int)curtime.tv_usec / 1000;
302 }
303#endif
304
305 // Print the log message.
306 int64_t pid = os_get_pid();
307 int rv = (line_num == -1 || func_name == NULL)
308 ? fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s",
309 log_levels[log_level], date_time, millis, pid,
310 (context == NULL ? "?:" : context))
311 : fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s%s:%d: ",
312 log_levels[log_level], date_time, millis, pid,
313 (context == NULL ? "" : context),
314 func_name, line_num);
315 if (rv < 0) {
316 return false;
317 }
318 if (vfprintf(log_file, fmt, args) < 0) {
319 return false;
320 }
321 if (eol) {
322 fputc('\n', log_file);
323 }
324 if (fflush(log_file) == EOF) {
325 return false;
326 }
327
328 return true;
329}
330
331