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(). |
30 | static char log_file_path[MAXPATHL + 1] = { 0 }; |
31 | |
32 | static 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 | |
42 | static 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. |
63 | static 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 | |
93 | void log_init(void) |
94 | { |
95 | uv_mutex_init(&mutex); |
96 | } |
97 | |
98 | void log_lock(void) |
99 | { |
100 | uv_mutex_lock(&mutex); |
101 | } |
102 | |
103 | void 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 |
116 | bool 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 | } |
147 | end: |
148 | log_unlock(); |
149 | return ret; |
150 | } |
151 | |
152 | void 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 | } |
167 | end: |
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 |
174 | FILE *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 |
207 | void 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 | |
244 | void 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 | |
254 | end: |
255 | log_unlock(); |
256 | } |
257 | #endif |
258 | |
259 | static 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 | |
273 | static 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 | |