/src/core/libntech/libutils/logging.c
Line | Count | Source (jump to first uncovered line) |
1 | | /* |
2 | | Copyright 2023 Northern.tech AS |
3 | | |
4 | | This file is part of CFEngine 3 - written and maintained by Northern.tech AS. |
5 | | |
6 | | Licensed under the Apache License, Version 2.0 (the "License"); |
7 | | you may not use this file except in compliance with the License. |
8 | | You may obtain a copy of the License at |
9 | | |
10 | | http://www.apache.org/licenses/LICENSE-2.0 |
11 | | |
12 | | Unless required by applicable law or agreed to in writing, software |
13 | | distributed under the License is distributed on an "AS IS" BASIS, |
14 | | WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
15 | | See the License for the specific language governing permissions and |
16 | | limitations under the License. |
17 | | |
18 | | To the extent this program is licensed as part of the Enterprise |
19 | | versions of CFEngine, the applicable Commercial Open Source License |
20 | | (COSL) may apply to this file if you as a licensee so wish it. See |
21 | | included file COSL.txt. |
22 | | */ |
23 | | |
24 | | #include <platform.h> |
25 | | #include <logging.h> |
26 | | #include <alloc.h> |
27 | | #include <string_lib.h> |
28 | | #include <misc_lib.h> |
29 | | #include <cleanup.h> |
30 | | #include <sequence.h> |
31 | | |
32 | | #if defined(HAVE_SYSTEMD_SD_JOURNAL_H) && defined(HAVE_LIBSYSTEMD) |
33 | | #include <systemd/sd-journal.h> /* sd_journal_sendv() */ |
34 | | #endif // defined(HAVE_SYSTEMD_SD_JOURNAL_H) && defined(HAVE_LIBSYSTEMD) |
35 | | |
36 | | #include <definitions.h> /* CF_BUFSIZE */ |
37 | | |
38 | | char VPREFIX[1024] = ""; /* GLOBAL_C */ |
39 | | |
40 | | static char AgentType[80] = "generic"; |
41 | | static bool TIMESTAMPS = false; |
42 | | |
43 | | static LogLevel global_level = LOG_LEVEL_NOTICE; /* GLOBAL_X */ |
44 | | static LogLevel global_system_log_level = LOG_LEVEL_NOTHING; /* default value that means not set */ |
45 | | |
46 | | static pthread_once_t log_context_init_once = PTHREAD_ONCE_INIT; /* GLOBAL_T */ |
47 | | static pthread_key_t log_context_key; /* GLOBAL_T, initialized by pthread_key_create */ |
48 | | |
49 | | static Seq *log_buffer = NULL; |
50 | | static bool logging_into_buffer = false; |
51 | | static LogLevel min_log_into_buffer_level = LOG_LEVEL_NOTHING; |
52 | | static LogLevel max_log_into_buffer_level = LOG_LEVEL_NOTHING; |
53 | | |
54 | | typedef struct LogEntry_ |
55 | | { |
56 | | LogLevel level; |
57 | | char *msg; |
58 | | } LogEntry; |
59 | | |
60 | | static void LoggingInitializeOnce(void) |
61 | 0 | { |
62 | 0 | if (pthread_key_create(&log_context_key, &free) != 0) |
63 | 0 | { |
64 | | /* There is no way to signal error out of pthread_once callback. |
65 | | * However if pthread_key_create fails we are pretty much guaranteed |
66 | | * that nothing else will work. */ |
67 | |
|
68 | 0 | fprintf(stderr, "Unable to initialize logging subsystem\n"); |
69 | 0 | DoCleanupAndExit(255); |
70 | 0 | } |
71 | 0 | } |
72 | | |
73 | | LoggingContext *GetCurrentThreadContext(void) |
74 | 0 | { |
75 | 0 | pthread_once(&log_context_init_once, &LoggingInitializeOnce); |
76 | 0 | LoggingContext *lctx = pthread_getspecific(log_context_key); |
77 | 0 | if (lctx == NULL) |
78 | 0 | { |
79 | 0 | lctx = xcalloc(1, sizeof(LoggingContext)); |
80 | 0 | lctx->log_level = (global_system_log_level != LOG_LEVEL_NOTHING ? |
81 | 0 | global_system_log_level : |
82 | 0 | global_level); |
83 | 0 | lctx->report_level = global_level; |
84 | 0 | pthread_setspecific(log_context_key, lctx); |
85 | 0 | } |
86 | 0 | return lctx; |
87 | 0 | } |
88 | | |
89 | | void LoggingFreeCurrentThreadContext(void) |
90 | 0 | { |
91 | 0 | pthread_once(&log_context_init_once, &LoggingInitializeOnce); |
92 | 0 | LoggingContext *lctx = pthread_getspecific(log_context_key); |
93 | 0 | if (lctx == NULL) |
94 | 0 | { |
95 | 0 | return; |
96 | 0 | } |
97 | | // lctx->pctx is usually stack allocated and shouldn't be freed |
98 | 0 | FREE_AND_NULL(lctx); |
99 | 0 | pthread_setspecific(log_context_key, NULL); |
100 | 0 | } |
101 | | |
102 | | void LoggingSetAgentType(const char *type) |
103 | 0 | { |
104 | 0 | strlcpy(AgentType, type, sizeof(AgentType)); |
105 | 0 | } |
106 | | |
107 | | void LoggingEnableTimestamps(bool enable) |
108 | 0 | { |
109 | 0 | TIMESTAMPS = enable; |
110 | 0 | } |
111 | | |
112 | | void LoggingPrivSetContext(LoggingPrivContext *pctx) |
113 | 0 | { |
114 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
115 | 0 | lctx->pctx = pctx; |
116 | 0 | } |
117 | | |
118 | | LoggingPrivContext *LoggingPrivGetContext(void) |
119 | 0 | { |
120 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
121 | 0 | return lctx->pctx; |
122 | 0 | } |
123 | | |
124 | | void LoggingPrivSetLevels(LogLevel log_level, LogLevel report_level) |
125 | 0 | { |
126 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
127 | 0 | lctx->log_level = log_level; |
128 | 0 | lctx->report_level = report_level; |
129 | 0 | } |
130 | | |
131 | | const char *LogLevelToString(LogLevel level) |
132 | 0 | { |
133 | 0 | switch (level) |
134 | 0 | { |
135 | 0 | case LOG_LEVEL_CRIT: |
136 | 0 | return "CRITICAL"; |
137 | 0 | case LOG_LEVEL_ERR: |
138 | 0 | return "error"; |
139 | 0 | case LOG_LEVEL_WARNING: |
140 | 0 | return "warning"; |
141 | 0 | case LOG_LEVEL_NOTICE: |
142 | 0 | return "notice"; |
143 | 0 | case LOG_LEVEL_INFO: |
144 | 0 | return "info"; |
145 | 0 | case LOG_LEVEL_VERBOSE: |
146 | 0 | return "verbose"; |
147 | 0 | case LOG_LEVEL_DEBUG: |
148 | 0 | return "debug"; |
149 | 0 | default: |
150 | 0 | ProgrammingError("LogLevelToString: Unexpected log level %d", level); |
151 | 0 | } |
152 | 0 | } |
153 | | |
154 | | LogLevel LogLevelFromString(const char *const level) |
155 | 0 | { |
156 | | // Only compare the part the user typed |
157 | | // i/info/inform/information will all result in LOG_LEVEL_INFO |
158 | 0 | size_t len = SafeStringLength(level); |
159 | 0 | if (len == 0) |
160 | 0 | { |
161 | 0 | return LOG_LEVEL_NOTHING; |
162 | 0 | } |
163 | 0 | if (StringEqualN_IgnoreCase(level, "CRITICAL", len)) |
164 | 0 | { |
165 | 0 | return LOG_LEVEL_CRIT; |
166 | 0 | } |
167 | 0 | if (StringEqualN_IgnoreCase(level, "errors", len)) |
168 | 0 | { |
169 | 0 | return LOG_LEVEL_ERR; |
170 | 0 | } |
171 | 0 | if (StringEqualN_IgnoreCase(level, "warnings", len)) |
172 | 0 | { |
173 | 0 | return LOG_LEVEL_WARNING; |
174 | 0 | } |
175 | 0 | if (StringEqualN_IgnoreCase(level, "notices", len)) |
176 | 0 | { |
177 | 0 | return LOG_LEVEL_NOTICE; |
178 | 0 | } |
179 | 0 | if (StringEqualN_IgnoreCase(level, "information", len)) |
180 | 0 | { |
181 | 0 | return LOG_LEVEL_INFO; |
182 | 0 | } |
183 | 0 | if (StringEqualN_IgnoreCase(level, "verbose", len)) |
184 | 0 | { |
185 | 0 | return LOG_LEVEL_VERBOSE; |
186 | 0 | } |
187 | 0 | if (StringEqualN_IgnoreCase(level, "debug", len)) |
188 | 0 | { |
189 | 0 | return LOG_LEVEL_DEBUG; |
190 | 0 | } |
191 | 0 | return LOG_LEVEL_NOTHING; |
192 | 0 | } |
193 | | |
194 | | static const char *LogLevelToColor(LogLevel level) |
195 | 0 | { |
196 | |
|
197 | 0 | switch (level) |
198 | 0 | { |
199 | 0 | case LOG_LEVEL_CRIT: |
200 | 0 | case LOG_LEVEL_ERR: |
201 | 0 | return "\x1b[31m"; // red |
202 | | |
203 | 0 | case LOG_LEVEL_WARNING: |
204 | 0 | return "\x1b[33m"; // yellow |
205 | | |
206 | 0 | case LOG_LEVEL_NOTICE: |
207 | 0 | case LOG_LEVEL_INFO: |
208 | 0 | return "\x1b[32m"; // green |
209 | | |
210 | 0 | case LOG_LEVEL_VERBOSE: |
211 | 0 | case LOG_LEVEL_DEBUG: |
212 | 0 | return "\x1b[34m"; // blue |
213 | | |
214 | 0 | default: |
215 | 0 | ProgrammingError("LogLevelToColor: Unexpected log level %d", level); |
216 | 0 | } |
217 | 0 | } |
218 | | |
219 | | bool LoggingFormatTimestamp(char dest[64], size_t n, struct tm *timestamp) |
220 | 0 | { |
221 | 0 | if (strftime(dest, n, "%Y-%m-%dT%H:%M:%S%z", timestamp) == 0) |
222 | 0 | { |
223 | 0 | strlcpy(dest, "<unknown>", n); |
224 | 0 | return false; |
225 | 0 | } |
226 | 0 | return true; |
227 | 0 | } |
228 | | |
229 | | static void LogToConsole(const char *msg, LogLevel level, bool color) |
230 | 0 | { |
231 | 0 | struct tm now; |
232 | 0 | time_t now_seconds = time(NULL); |
233 | 0 | localtime_r(&now_seconds, &now); |
234 | |
|
235 | 0 | if (color) |
236 | 0 | { |
237 | 0 | fprintf(stdout, "%s", LogLevelToColor(level)); |
238 | 0 | } |
239 | 0 | if (level >= LOG_LEVEL_INFO && VPREFIX[0]) |
240 | 0 | { |
241 | 0 | fprintf(stdout, "%s ", VPREFIX); |
242 | 0 | } |
243 | 0 | if (TIMESTAMPS) |
244 | 0 | { |
245 | 0 | char formatted_timestamp[64]; |
246 | 0 | LoggingFormatTimestamp(formatted_timestamp, 64, &now); |
247 | 0 | fprintf(stdout, "%s ", formatted_timestamp); |
248 | 0 | } |
249 | |
|
250 | 0 | fprintf(stdout, "%8s: %s\n", LogLevelToString(level), msg); |
251 | |
|
252 | 0 | if (color) |
253 | 0 | { |
254 | | // Turn off the color again. |
255 | 0 | fprintf(stdout, "\x1b[0m"); |
256 | 0 | } |
257 | |
|
258 | 0 | fflush(stdout); |
259 | 0 | } |
260 | | |
261 | | #if !defined(__MINGW32__) |
262 | | static int LogLevelToSyslogPriority(LogLevel level) |
263 | 0 | { |
264 | 0 | switch (level) |
265 | 0 | { |
266 | 0 | case LOG_LEVEL_CRIT: return LOG_CRIT; |
267 | 0 | case LOG_LEVEL_ERR: return LOG_ERR; |
268 | 0 | case LOG_LEVEL_WARNING: return LOG_WARNING; |
269 | 0 | case LOG_LEVEL_NOTICE: return LOG_NOTICE; |
270 | 0 | case LOG_LEVEL_INFO: return LOG_INFO; |
271 | 0 | case LOG_LEVEL_VERBOSE: return LOG_DEBUG; /* FIXME: Do we really want to conflate those levels? */ |
272 | 0 | case LOG_LEVEL_DEBUG: return LOG_DEBUG; |
273 | 0 | default: |
274 | 0 | ProgrammingError("LogLevelToSyslogPriority: Unexpected log level %d", |
275 | 0 | level); |
276 | 0 | } |
277 | |
|
278 | 0 | } |
279 | | |
280 | | void LogToSystemLog(const char *msg, LogLevel level) |
281 | 0 | { |
282 | 0 | char logmsg[4096]; |
283 | 0 | snprintf(logmsg, sizeof(logmsg), "CFEngine(%s) %s %s\n", AgentType, VPREFIX, msg); |
284 | 0 | syslog(LogLevelToSyslogPriority(level), "%s", logmsg); |
285 | 0 | } |
286 | | #endif /* !__MINGW32__ */ |
287 | | |
288 | | #if defined(HAVE_SYSTEMD_SD_JOURNAL_H) && defined(HAVE_LIBSYSTEMD) |
289 | | void LogToSystemLogStructured(const int level, ...) |
290 | | { |
291 | | va_list args; |
292 | | va_start(args, level); |
293 | | |
294 | | // Additional pairs |
295 | | Seq *const seq = SeqNew(2, free); |
296 | | for (const char *key = va_arg(args, char *); !StringEqual(key, "MESSAGE"); |
297 | | key = va_arg(args, char *)) |
298 | | { |
299 | | const char *const value = va_arg(args, char *); |
300 | | char *const pair = StringFormat("%s=%s", key, value); |
301 | | SeqAppend(seq, pair); |
302 | | } |
303 | | |
304 | | // Message pair |
305 | | const char *const format_str = va_arg(args, char *); |
306 | | char *const message = StringVFormat(format_str, args); |
307 | | char *pair = StringFormat("MESSAGE=%s", message); |
308 | | free(message); |
309 | | SeqAppend(seq, pair); |
310 | | |
311 | | // Priority pair |
312 | | const int priority = LogLevelToSyslogPriority(level); |
313 | | pair = StringFormat("PRIORITY=%i", priority); |
314 | | SeqAppend(seq, pair); |
315 | | |
316 | | const int num_pairs = SeqLength(seq); |
317 | | struct iovec iov[num_pairs]; |
318 | | for (int i = 0; i < num_pairs; i++) |
319 | | { |
320 | | iov[i].iov_base = SeqAt(seq, i); |
321 | | iov[i].iov_len = strlen(iov[i].iov_base); |
322 | | } |
323 | | |
324 | | NDEBUG_UNUSED int ret = sd_journal_sendv(iov, num_pairs); |
325 | | assert(ret == 0); |
326 | | SeqDestroy(seq); |
327 | | va_end(args); |
328 | | } |
329 | | #else // defined(HAVE_SYSTEMD_SD_JOURNAL_H) && defined(HAVE_LIBSYSTEMD) |
330 | | void LogToSystemLogStructured(const int level, ...) |
331 | 0 | { |
332 | 0 | va_list args; |
333 | 0 | va_start(args, level); |
334 | |
|
335 | 0 | for (const char *key = va_arg(args, char *); !StringEqual(key, "MESSAGE"); |
336 | 0 | key = va_arg(args, char *)) |
337 | 0 | { |
338 | 0 | va_arg(args, char *); |
339 | 0 | } |
340 | |
|
341 | 0 | const char *const format_str = va_arg(args, char *); |
342 | 0 | char *const message = StringVFormat(format_str, args); |
343 | 0 | LogToSystemLog(message, level); |
344 | 0 | free(message); |
345 | 0 | va_end(args); |
346 | 0 | } |
347 | | #endif // defined(HAVE_SYSTEMD_SD_JOURNAL_H) && defined(HAVE_LIBSYSTEMD) |
348 | | |
349 | | void __ImproperUseOfLogToSystemLogStructured(void) |
350 | 0 | { |
351 | | // TODO: CFE-4190 |
352 | | // - Make sure CodeQL finds at least the reqired function calls below, |
353 | | // then remove this code |
354 | 0 | assert(false); // Do not use this function! |
355 | | |
356 | | // Required: Missing required "MESSAGE" key. |
357 | 0 | LogToSystemLogStructured(LOG_LEVEL_DEBUG, "FOO", "bogus", "BAR", "doofus"); |
358 | | |
359 | | // Required: String-literal "MESSAGE" is not the same as "message". |
360 | 0 | LogToSystemLogStructured(LOG_LEVEL_INFO, "FOO", "bogus", "BAR", "doofus", "message", "Hello CFEngine!"); |
361 | | |
362 | | // Required: Number of format-string arguments is less than number of format specifiers. |
363 | 0 | LogToSystemLogStructured(LOG_LEVEL_ERR, "MESSAGE", "%s %d", "CFEngine"); |
364 | | |
365 | | // Optional: Number of format-string arguments is greated than number of format specifiers. |
366 | 0 | LogToSystemLogStructured(LOG_LEVEL_ERR, "MESSAGE", "%s %d", "CFEngine", 123, "ROCKS!"); |
367 | | |
368 | | // Optional: All keys must be uppercase or else they are ignored. |
369 | 0 | LogToSystemLogStructured(LOG_LEVEL_CRIT, "FOO", "bogus", "bar", "DOOFUS", "MESSAGE", "Hello CFEngine!"); |
370 | | |
371 | | // Optional: Pairs trailing the "MESSAGE" key are ignored. |
372 | 0 | LogToSystemLogStructured(LOG_LEVEL_NOTICE, "FOO", "bogus", "MESSAGE", "Hello CFEngine!", "BAR", "doofus"); |
373 | 0 | } |
374 | | |
375 | | #ifndef __MINGW32__ |
376 | | const char *GetErrorStrFromCode(int error_code) |
377 | 0 | { |
378 | 0 | return strerror(error_code); |
379 | 0 | } |
380 | | |
381 | | const char *GetErrorStr(void) |
382 | 0 | { |
383 | 0 | return strerror(errno); |
384 | 0 | } |
385 | | |
386 | | #else |
387 | | |
388 | | const char *GetErrorStrFromCode(int error_code) |
389 | | { |
390 | | static char errbuf[CF_BUFSIZE]; |
391 | | int len; |
392 | | |
393 | | memset(errbuf, 0, sizeof(errbuf)); |
394 | | |
395 | | if (FormatMessage(FORMAT_MESSAGE_FROM_SYSTEM, NULL, error_code, |
396 | | MAKELANGID(LANG_ENGLISH, SUBLANG_ENGLISH_US), errbuf, CF_BUFSIZE, NULL)) |
397 | | { |
398 | | // remove CRLF from end |
399 | | len = strlen(errbuf); |
400 | | errbuf[len - 2] = errbuf[len - 1] = '\0'; |
401 | | } else { |
402 | | strcpy(errbuf, "Unknown error"); |
403 | | } |
404 | | |
405 | | return errbuf; |
406 | | } |
407 | | |
408 | | const char *GetErrorStr(void) |
409 | | { |
410 | | return GetErrorStrFromCode(GetLastError()); |
411 | | } |
412 | | #endif /* !__MINGW32__ */ |
413 | | |
414 | | bool WouldLog(LogLevel level) |
415 | 0 | { |
416 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
417 | |
|
418 | 0 | bool log_to_console = (level <= lctx->report_level); |
419 | 0 | bool log_to_syslog = (level <= lctx->log_level && |
420 | 0 | level < LOG_LEVEL_VERBOSE); |
421 | 0 | bool force_hook = (lctx->pctx && |
422 | 0 | lctx->pctx->log_hook && |
423 | 0 | lctx->pctx->force_hook_level >= level); |
424 | |
|
425 | 0 | return (log_to_console || log_to_syslog || force_hook); |
426 | 0 | } |
427 | | |
428 | | /** |
429 | | * #no_format determines whether #fmt_msg is interpreted as a format string and |
430 | | * combined with #ap to create the real log message (%false) or as a log message |
431 | | * dirrectly (%true) in which case #ap is ignored. |
432 | | * |
433 | | * @see LogNoFormat() |
434 | | */ |
435 | | static void VLogNoFormat(LogLevel level, const char *fmt_msg, va_list ap, bool no_format) |
436 | 0 | { |
437 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
438 | |
|
439 | 0 | bool log_to_console = ( level <= lctx->report_level ); |
440 | 0 | bool log_to_syslog = ( level <= lctx->log_level && |
441 | 0 | level < LOG_LEVEL_VERBOSE ); |
442 | 0 | bool force_hook = ( lctx->pctx && |
443 | 0 | lctx->pctx->log_hook && |
444 | 0 | lctx->pctx->force_hook_level >= level ); |
445 | | |
446 | | /* NEEDS TO BE IN SYNC WITH THE CONDITION IN WouldLog() ABOVE! */ |
447 | 0 | if (!log_to_console && !log_to_syslog && !force_hook) |
448 | 0 | { |
449 | 0 | return; /* early return - save resources */ |
450 | 0 | } |
451 | | |
452 | 0 | char *msg; |
453 | 0 | if (no_format) |
454 | 0 | { |
455 | 0 | msg = xstrdup(fmt_msg); |
456 | 0 | } |
457 | 0 | else |
458 | 0 | { |
459 | 0 | msg = StringVFormat(fmt_msg, ap); |
460 | 0 | } |
461 | 0 | char *hooked_msg = NULL; |
462 | |
|
463 | 0 | if (logging_into_buffer && |
464 | 0 | (level >= min_log_into_buffer_level) && (level <= max_log_into_buffer_level)) |
465 | 0 | { |
466 | 0 | assert(log_buffer != NULL); |
467 | |
|
468 | 0 | if (log_buffer == NULL) |
469 | 0 | { |
470 | | /* Should never happen. */ |
471 | 0 | Log(LOG_LEVEL_ERR, |
472 | 0 | "Attempt to log a message to an unitialized log buffer, discarding the message"); |
473 | 0 | } |
474 | |
|
475 | 0 | LogEntry *entry = xmalloc(sizeof(LogEntry)); |
476 | 0 | entry->level = level; |
477 | 0 | entry->msg = msg; |
478 | |
|
479 | 0 | SeqAppend(log_buffer, entry); |
480 | 0 | return; |
481 | 0 | } |
482 | | |
483 | | /* Remove ending EOLN. */ |
484 | 0 | for (char *sp = msg; *sp != '\0'; sp++) |
485 | 0 | { |
486 | 0 | if (*sp == '\n' && *(sp+1) == '\0') |
487 | 0 | { |
488 | 0 | *sp = '\0'; |
489 | 0 | break; |
490 | 0 | } |
491 | 0 | } |
492 | |
|
493 | 0 | if (lctx->pctx && lctx->pctx->log_hook) |
494 | 0 | { |
495 | 0 | hooked_msg = lctx->pctx->log_hook(lctx->pctx, level, msg); |
496 | 0 | } |
497 | 0 | else |
498 | 0 | { |
499 | 0 | hooked_msg = msg; |
500 | 0 | } |
501 | |
|
502 | 0 | if (log_to_console) |
503 | 0 | { |
504 | 0 | LogToConsole(hooked_msg, level, lctx->color); |
505 | 0 | } |
506 | 0 | if (log_to_syslog) |
507 | 0 | { |
508 | 0 | LogToSystemLogStructured(level, "MESSAGE", "%s", hooked_msg); |
509 | 0 | } |
510 | |
|
511 | 0 | if (hooked_msg != msg) |
512 | 0 | { |
513 | 0 | free(hooked_msg); |
514 | 0 | } |
515 | 0 | free(msg); |
516 | 0 | } |
517 | | |
518 | | void VLog(LogLevel level, const char *fmt, va_list ap) |
519 | 0 | { |
520 | 0 | VLogNoFormat(level, fmt, ap, false); |
521 | 0 | } |
522 | | |
523 | | /** |
524 | | * @brief Logs binary data in #buf, with unprintable bytes translated to '.'. |
525 | | * Message is prefixed with #prefix. |
526 | | * @param #buflen must be no more than CF_BUFSIZE |
527 | | */ |
528 | | void LogRaw(LogLevel level, const char *prefix, const void *buf, size_t buflen) |
529 | 0 | { |
530 | 0 | if (buflen > CF_BUFSIZE) |
531 | 0 | { |
532 | 0 | debug_abort_if_reached(); |
533 | 0 | buflen = CF_BUFSIZE; |
534 | 0 | } |
535 | |
|
536 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
537 | 0 | if (level <= lctx->report_level || level <= lctx->log_level) |
538 | 0 | { |
539 | 0 | const unsigned char *src = buf; |
540 | 0 | unsigned char dst[CF_BUFSIZE+1]; |
541 | 0 | assert(buflen < sizeof(dst)); |
542 | 0 | size_t i; |
543 | 0 | for (i = 0; i < buflen; i++) |
544 | 0 | { |
545 | 0 | dst[i] = isprint(src[i]) ? src[i] : '.'; |
546 | 0 | } |
547 | 0 | assert(i < sizeof(dst)); |
548 | 0 | dst[i] = '\0'; |
549 | | |
550 | | /* And Log the translated buffer, which is now a valid string. */ |
551 | 0 | Log(level, "%s%s", prefix, dst); |
552 | 0 | } |
553 | 0 | } |
554 | | |
555 | | void Log(LogLevel level, const char *fmt, ...) |
556 | 0 | { |
557 | 0 | va_list ap; |
558 | 0 | va_start(ap, fmt); |
559 | 0 | VLog(level, fmt, ap); |
560 | 0 | va_end(ap); |
561 | 0 | } |
562 | | |
563 | | /** |
564 | | * The same as above, but for logging messages without formatting sequences |
565 | | * ("%s", "%d",...). Or more precisely, for *safe* logging of messages that may |
566 | | * contain such sequences (for example Log(LOG_LEVEL_ERR, "%s") can potentially |
567 | | * log some secrets). |
568 | | * |
569 | | * It doesn't have the FUNC_ATTR_PRINTF restriction that causes a compilation |
570 | | * warning/error if #msg is not a constant string. |
571 | | * |
572 | | * @note This is for special cases where #msg was already printf-like formatted, |
573 | | * the variadic arguments are ignored, they are here just so that |
574 | | * 'va_list ap' can be constructed and passed to VLogNoFormat(). |
575 | | * |
576 | | * @see CommitLogBuffer() |
577 | | */ |
578 | | static void LogNoFormat(LogLevel level, const char *msg, ...) |
579 | 0 | { |
580 | 0 | va_list ap; |
581 | 0 | va_start(ap, msg); |
582 | 0 | VLogNoFormat(level, msg, ap, true); |
583 | 0 | va_end(ap); |
584 | 0 | } |
585 | | |
586 | | static bool module_is_enabled[LOG_MOD_MAX]; |
587 | | static const char *log_modules[LOG_MOD_MAX] = |
588 | | { |
589 | | "", |
590 | | "evalctx", |
591 | | "expand", |
592 | | "iterations", |
593 | | "parser", |
594 | | "vartable", |
595 | | "vars", |
596 | | "locks", |
597 | | "ps", |
598 | | }; |
599 | | |
600 | | static enum LogModule LogModuleFromString(const char *s) |
601 | 0 | { |
602 | 0 | for (enum LogModule i = 0; i < LOG_MOD_MAX; i++) |
603 | 0 | { |
604 | 0 | if (strcmp(log_modules[i], s) == 0) |
605 | 0 | { |
606 | 0 | return i; |
607 | 0 | } |
608 | 0 | } |
609 | | |
610 | 0 | return LOG_MOD_NONE; |
611 | 0 | } |
612 | | |
613 | | void LogEnableModule(enum LogModule mod) |
614 | 0 | { |
615 | 0 | assert(mod < LOG_MOD_MAX); |
616 | |
|
617 | 0 | module_is_enabled[mod] = true; |
618 | 0 | } |
619 | | |
620 | | void LogModuleHelp(void) |
621 | 0 | { |
622 | 0 | printf("\n--log-modules accepts a comma separated list of one or more of the following:\n\n"); |
623 | 0 | printf(" help\n"); |
624 | 0 | printf(" all\n"); |
625 | 0 | for (enum LogModule i = LOG_MOD_NONE + 1; i < LOG_MOD_MAX; i++) |
626 | 0 | { |
627 | 0 | printf(" %s\n", log_modules[i]); |
628 | 0 | } |
629 | 0 | printf("\n"); |
630 | 0 | } |
631 | | |
632 | | /** |
633 | | * Parse a string of modules, and enable the relevant DEBUG logging modules. |
634 | | * Example strings: |
635 | | * |
636 | | * all : enables all debug modules |
637 | | * help : enables nothing, but prints a help message |
638 | | * iterctx : enables the "iterctx" debug logging module |
639 | | * iterctx,vars: enables the 2 debug modules, "iterctx" and "vars" |
640 | | * |
641 | | * @NOTE modifies string #s but restores it before returning. |
642 | | */ |
643 | | bool LogEnableModulesFromString(char *s) |
644 | 0 | { |
645 | 0 | bool retval = true; |
646 | |
|
647 | 0 | const char *token = s; |
648 | 0 | char saved_sep = ','; /* any non-NULL value will do */ |
649 | 0 | while (saved_sep != '\0' && retval != false) |
650 | 0 | { |
651 | 0 | char *next_token = strchrnul(token, ','); |
652 | 0 | saved_sep = *next_token; |
653 | 0 | *next_token = '\0'; /* modify parameter s */ |
654 | 0 | size_t token_len = next_token - token; |
655 | |
|
656 | 0 | if (strcmp(token, "help") == 0) |
657 | 0 | { |
658 | 0 | LogModuleHelp(); |
659 | 0 | retval = false; /* early exit */ |
660 | 0 | } |
661 | 0 | else if (strcmp(token, "all") == 0) |
662 | 0 | { |
663 | 0 | for (enum LogModule j = LOG_MOD_NONE + 1; j < LOG_MOD_MAX; j++) |
664 | 0 | { |
665 | 0 | LogEnableModule(j); |
666 | 0 | } |
667 | 0 | } |
668 | 0 | else |
669 | 0 | { |
670 | 0 | enum LogModule mod = LogModuleFromString(token); |
671 | |
|
672 | 0 | assert(mod < LOG_MOD_MAX); |
673 | 0 | if (mod == LOG_MOD_NONE) |
674 | 0 | { |
675 | 0 | Log(LOG_LEVEL_WARNING, |
676 | 0 | "Unknown debug logging module '%*s'", |
677 | 0 | (int) token_len, token); |
678 | 0 | } |
679 | 0 | else |
680 | 0 | { |
681 | 0 | LogEnableModule(mod); |
682 | 0 | } |
683 | 0 | } |
684 | | |
685 | |
|
686 | 0 | *next_token = saved_sep; /* restore modified parameter s */ |
687 | 0 | next_token++; /* bypass comma */ |
688 | 0 | token = next_token; |
689 | 0 | } |
690 | |
|
691 | 0 | return retval; |
692 | 0 | } |
693 | | |
694 | | bool LogModuleEnabled(enum LogModule mod) |
695 | 0 | { |
696 | 0 | assert(mod > LOG_MOD_NONE); |
697 | 0 | assert(mod < LOG_MOD_MAX); |
698 | |
|
699 | 0 | if (module_is_enabled[mod]) |
700 | 0 | { |
701 | 0 | return true; |
702 | 0 | } |
703 | 0 | else |
704 | 0 | { |
705 | 0 | return false; |
706 | 0 | } |
707 | 0 | } |
708 | | |
709 | | void LogDebug(enum LogModule mod, const char *fmt, ...) |
710 | 0 | { |
711 | 0 | assert(mod < LOG_MOD_MAX); |
712 | | |
713 | | /* Did we forget any entry in log_modules? */ |
714 | 0 | nt_static_assert(sizeof(log_modules) / sizeof(log_modules[0]) == LOG_MOD_MAX); |
715 | |
|
716 | 0 | if (LogModuleEnabled(mod)) |
717 | 0 | { |
718 | 0 | va_list ap; |
719 | 0 | va_start(ap, fmt); |
720 | 0 | VLog(LOG_LEVEL_DEBUG, fmt, ap); |
721 | 0 | va_end(ap); |
722 | | /* VLog(LOG_LEVEL_DEBUG, "%s: ...", */ |
723 | | /* debug_modules_description[mod_order], ...); */ |
724 | 0 | } |
725 | 0 | } |
726 | | |
727 | | |
728 | | void LogSetGlobalLevel(LogLevel level) |
729 | 0 | { |
730 | 0 | global_level = level; |
731 | 0 | if (global_system_log_level == LOG_LEVEL_NOTHING) |
732 | 0 | { |
733 | 0 | LoggingPrivSetLevels(level, level); |
734 | 0 | } |
735 | 0 | else |
736 | 0 | { |
737 | 0 | LoggingPrivSetLevels(global_system_log_level, level); |
738 | 0 | } |
739 | 0 | } |
740 | | |
741 | | void LogSetGlobalLevelArgOrExit(const char *const arg) |
742 | 0 | { |
743 | 0 | LogLevel level = LogLevelFromString(arg); |
744 | 0 | if (level == LOG_LEVEL_NOTHING) |
745 | 0 | { |
746 | | // This function is used as part of initializing the logging |
747 | | // system. Using Log() can be considered incorrect, even though |
748 | | // it may "work". Let's just print an error to stderr: |
749 | 0 | fprintf(stderr, "Invalid log level: '%s'\n", arg); |
750 | 0 | DoCleanupAndExit(1); |
751 | 0 | } |
752 | 0 | LogSetGlobalLevel(level); |
753 | 0 | } |
754 | | |
755 | | LogLevel LogGetGlobalLevel(void) |
756 | 0 | { |
757 | 0 | return global_level; |
758 | 0 | } |
759 | | |
760 | | void LogSetGlobalSystemLogLevel(LogLevel level) |
761 | 0 | { |
762 | | /* LOG_LEVEL_NOTHING means "unset" (see LogUnsetGlobalSystemLogLevel()) */ |
763 | 0 | assert(level != LOG_LEVEL_NOTHING); |
764 | |
|
765 | 0 | global_system_log_level = level; |
766 | 0 | LoggingPrivSetLevels(level, global_level); |
767 | 0 | } |
768 | | |
769 | | void LogUnsetGlobalSystemLogLevel(void) |
770 | 0 | { |
771 | 0 | global_system_log_level = LOG_LEVEL_NOTHING; |
772 | 0 | LoggingPrivSetLevels(global_level, global_level); |
773 | 0 | } |
774 | | |
775 | | LogLevel LogGetGlobalSystemLogLevel(void) |
776 | 0 | { |
777 | 0 | return global_system_log_level; |
778 | 0 | } |
779 | | |
780 | | void LoggingSetColor(bool enabled) |
781 | 0 | { |
782 | 0 | LoggingContext *lctx = GetCurrentThreadContext(); |
783 | 0 | lctx->color = enabled; |
784 | 0 | } |
785 | | |
786 | | // byte_magnitude and byte_unit are used to print human readable byte counts |
787 | | long byte_magnitude(long bytes) |
788 | 0 | { |
789 | 0 | const long Ki = 1024; |
790 | 0 | const long Mi = Ki * 1024; |
791 | 0 | const long Gi = Mi * 1024; |
792 | |
|
793 | 0 | if (bytes > 8 * Gi) |
794 | 0 | { |
795 | 0 | return bytes / Gi; |
796 | 0 | } |
797 | 0 | else if (bytes > 8 * Mi) |
798 | 0 | { |
799 | 0 | return bytes / Mi; |
800 | 0 | } |
801 | 0 | else if (bytes > 8 * Ki) |
802 | 0 | { |
803 | 0 | return bytes / Ki; |
804 | 0 | } |
805 | 0 | return bytes; |
806 | 0 | } |
807 | | |
808 | | // Use this with byte_magnitude |
809 | | // Note that the cutoff is at 8x unit, because 3192 bytes is arguably more |
810 | | // useful than 3KiB |
811 | | const char *byte_unit(long bytes) |
812 | 0 | { |
813 | 0 | const long Ki = 1024; |
814 | 0 | const long Mi = Ki * 1024; |
815 | 0 | const long Gi = Mi * 1024; |
816 | |
|
817 | 0 | if (bytes > 8 * Gi) |
818 | 0 | { |
819 | 0 | return "GiB"; |
820 | 0 | } |
821 | 0 | else if (bytes > 8 * Mi) |
822 | 0 | { |
823 | 0 | return "MiB"; |
824 | 0 | } |
825 | 0 | else if (bytes > 8 * Ki) |
826 | 0 | { |
827 | 0 | return "KiB"; |
828 | 0 | } |
829 | 0 | return "bytes"; |
830 | 0 | } |
831 | | |
832 | | void LogEntryDestroy(LogEntry *entry) |
833 | 0 | { |
834 | 0 | if (entry != NULL) |
835 | 0 | { |
836 | 0 | free(entry->msg); |
837 | 0 | free(entry); |
838 | 0 | } |
839 | 0 | } |
840 | | |
841 | | void StartLoggingIntoBuffer(LogLevel min_level, LogLevel max_level) |
842 | 0 | { |
843 | 0 | assert((log_buffer == NULL) && (!logging_into_buffer)); |
844 | |
|
845 | 0 | if (log_buffer != NULL) |
846 | 0 | { |
847 | | /* Should never happen. */ |
848 | 0 | Log(LOG_LEVEL_ERR, "Re-initializing log buffer without prior commit, discarding messages"); |
849 | 0 | DiscardLogBuffer(); |
850 | 0 | } |
851 | |
|
852 | 0 | log_buffer = SeqNew(16, LogEntryDestroy); |
853 | 0 | logging_into_buffer = true; |
854 | 0 | min_log_into_buffer_level = min_level; |
855 | 0 | max_log_into_buffer_level = max_level; |
856 | 0 | } |
857 | | |
858 | | void DiscardLogBuffer() |
859 | 0 | { |
860 | 0 | SeqDestroy(log_buffer); |
861 | 0 | log_buffer = NULL; |
862 | 0 | logging_into_buffer = false; |
863 | 0 | } |
864 | | |
865 | | void CommitLogBuffer() |
866 | 0 | { |
867 | 0 | assert(logging_into_buffer); |
868 | 0 | assert(log_buffer != NULL); |
869 | |
|
870 | 0 | if (log_buffer == NULL) |
871 | 0 | { |
872 | | /* Should never happen. */ |
873 | 0 | Log(LOG_LEVEL_ERR, "Attempt to commit an unitialized log buffer"); |
874 | 0 | } |
875 | | |
876 | | /* Disable now so that LogNonConstant() below doesn't append the message |
877 | | * into the buffer instaed of logging it. */ |
878 | 0 | logging_into_buffer = false; |
879 | |
|
880 | 0 | const size_t n_entries = SeqLength(log_buffer); |
881 | 0 | for (size_t i = 0; i < n_entries; i++) |
882 | 0 | { |
883 | 0 | LogEntry *entry = SeqAt(log_buffer, i); |
884 | 0 | LogNoFormat(entry->level, entry->msg); |
885 | 0 | } |
886 | |
|
887 | 0 | DiscardLogBuffer(); |
888 | 0 | } |