cfengine  3.15.4
About: CFEngine is a configuration management system for configuring and maintaining Unix-like computers (using an own high level policy language). Community version.
  Fossies Dox: cfengine-3.15.4.tar.gz  ("unofficial" and yet experimental doxygen-generated source code documentation)  

logging.c
Go to the documentation of this file.
1 /*
2  Copyright 2020 Northern.tech AS
3 
4  This file is part of CFEngine 3 - written and maintained by Northern.tech AS.
5 
6  This program is free software; you can redistribute it and/or modify it
7  under the terms of the GNU General Public License as published by the
8  Free Software Foundation; version 3.
9 
10  This program is distributed in the hope that it will be useful,
11  but WITHOUT ANY WARRANTY; without even the implied warranty of
12  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
13  GNU General Public License for more details.
14 
15  You should have received a copy of the GNU General Public License
16  along with this program; if not, write to the Free Software
17  Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA
18 
19  To the extent this program is licensed as part of the Enterprise
20  versions of CFEngine, the applicable Commercial Open Source License
21  (COSL) may apply to this file if you as a licensee so wish it. See
22  included file COSL.txt.
23 */
24 
25 #include <logging.h>
26 #include <alloc.h>
27 #include <string_lib.h>
28 #include <misc_lib.h>
29 #include <cleanup.h>
30 
31 #include <definitions.h> /* CF_BUFSIZE */
32 
33 char VPREFIX[1024] = ""; /* GLOBAL_C */
34 
35 static char AgentType[80] = "generic";
36 static bool TIMESTAMPS = false;
37 
38 static LogLevel global_level = LOG_LEVEL_NOTICE; /* GLOBAL_X */
39 
40 static pthread_once_t log_context_init_once = PTHREAD_ONCE_INIT; /* GLOBAL_T */
41 static pthread_key_t log_context_key; /* GLOBAL_T, initialized by pthread_key_create */
42 
43 static void LoggingInitializeOnce(void)
44 {
45  if (pthread_key_create(&log_context_key, &free) != 0)
46  {
47  /* There is no way to signal error out of pthread_once callback.
48  * However if pthread_key_create fails we are pretty much guaranteed
49  * that nothing else will work. */
50 
51  fprintf(stderr, "Unable to initialize logging subsystem\n");
52  DoCleanupAndExit(255);
53  }
54 }
55 
57 {
59  LoggingContext *lctx = pthread_getspecific(log_context_key);
60  if (lctx == NULL)
61  {
62  lctx = xcalloc(1, sizeof(LoggingContext));
63  lctx->log_level = global_level;
64  lctx->report_level = global_level;
65  pthread_setspecific(log_context_key, lctx);
66  }
67  return lctx;
68 }
69 
71 {
73  LoggingContext *lctx = pthread_getspecific(log_context_key);
74  if (lctx == NULL)
75  {
76  return;
77  }
78  // lctx->pctx is usually stack allocated and shouldn't be freed
79  FREE_AND_NULL(lctx);
80  pthread_setspecific(log_context_key, NULL);
81 }
82 
83 void LoggingSetAgentType(const char *type)
84 {
85  strlcpy(AgentType, type, sizeof(AgentType));
86 }
87 
88 void LoggingEnableTimestamps(bool enable)
89 {
90  TIMESTAMPS = enable;
91 }
92 
94 {
96  lctx->pctx = pctx;
97 }
98 
100 {
102  return lctx->pctx;
103 }
104 
105 void LoggingPrivSetLevels(LogLevel log_level, LogLevel report_level)
106 {
108  lctx->log_level = log_level;
109  lctx->report_level = report_level;
110 }
111 
112 const char *LogLevelToString(LogLevel level)
113 {
114  switch (level)
115  {
116  case LOG_LEVEL_CRIT:
117  return "CRITICAL";
118  case LOG_LEVEL_ERR:
119  return "error";
120  case LOG_LEVEL_WARNING:
121  return "warning";
122  case LOG_LEVEL_NOTICE:
123  return "notice";
124  case LOG_LEVEL_INFO:
125  return "info";
126  case LOG_LEVEL_VERBOSE:
127  return "verbose";
128  case LOG_LEVEL_DEBUG:
129  return "debug";
130  default:
131  ProgrammingError("LogLevelToString: Unexpected log level %d", level);
132  }
133 }
134 
135 LogLevel LogLevelFromString(const char *const level)
136 {
137  // Only compare the part the user typed
138  // i/info/inform/information will all result in LOG_LEVEL_INFO
139  size_t len = SafeStringLength(level);
140  if (len == 0)
141  {
142  return LOG_LEVEL_NOTHING;
143  }
144  if (StringEqualN_IgnoreCase(level, "CRITICAL", len))
145  {
146  return LOG_LEVEL_CRIT;
147  }
148  if (StringEqualN_IgnoreCase(level, "errors", len))
149  {
150  return LOG_LEVEL_ERR;
151  }
152  if (StringEqualN_IgnoreCase(level, "warnings", len))
153  {
154  return LOG_LEVEL_WARNING;
155  }
156  if (StringEqualN_IgnoreCase(level, "notices", len))
157  {
158  return LOG_LEVEL_NOTICE;
159  }
160  if (StringEqualN_IgnoreCase(level, "information", len))
161  {
162  return LOG_LEVEL_INFO;
163  }
164  if (StringEqualN_IgnoreCase(level, "verbose", len))
165  {
166  return LOG_LEVEL_VERBOSE;
167  }
168  if (StringEqualN_IgnoreCase(level, "debug", len))
169  {
170  return LOG_LEVEL_DEBUG;
171  }
172  return LOG_LEVEL_NOTHING;
173 }
174 
175 static const char *LogLevelToColor(LogLevel level)
176 {
177 
178  switch (level)
179  {
180  case LOG_LEVEL_CRIT:
181  case LOG_LEVEL_ERR:
182  return "\x1b[31m"; // red
183 
184  case LOG_LEVEL_WARNING:
185  return "\x1b[33m"; // yellow
186 
187  case LOG_LEVEL_NOTICE:
188  case LOG_LEVEL_INFO:
189  return "\x1b[32m"; // green
190 
191  case LOG_LEVEL_VERBOSE:
192  case LOG_LEVEL_DEBUG:
193  return "\x1b[34m"; // blue
194 
195  default:
196  ProgrammingError("LogLevelToColor: Unexpected log level %d", level);
197  }
198 }
199 
200 bool LoggingFormatTimestamp(char dest[64], size_t n, struct tm *timestamp)
201 {
202  if (strftime(dest, n, "%Y-%m-%dT%H:%M:%S%z", timestamp) == 0)
203  {
204  strlcpy(dest, "<unknown>", n);
205  return false;
206  }
207  return true;
208 }
209 
210 static void LogToConsole(const char *msg, LogLevel level, bool color)
211 {
212  struct tm now;
213  time_t now_seconds = time(NULL);
214  localtime_r(&now_seconds, &now);
215 
216  if (color)
217  {
218  fprintf(stdout, "%s", LogLevelToColor(level));
219  }
220  if (level >= LOG_LEVEL_INFO && VPREFIX[0])
221  {
222  fprintf(stdout, "%s ", VPREFIX);
223  }
224  if (TIMESTAMPS)
225  {
226  char formatted_timestamp[64];
227  LoggingFormatTimestamp(formatted_timestamp, 64, &now);
228  fprintf(stdout, "%s ", formatted_timestamp);
229  }
230 
231  fprintf(stdout, "%8s: %s\n", LogLevelToString(level), msg);
232 
233  if (color)
234  {
235  // Turn off the color again.
236  fprintf(stdout, "\x1b[0m");
237  }
238 
239  fflush(stdout);
240 }
241 
242 #if !defined(__MINGW32__)
244 {
245  switch (level)
246  {
247  case LOG_LEVEL_CRIT: return LOG_CRIT;
248  case LOG_LEVEL_ERR: return LOG_ERR;
249  case LOG_LEVEL_WARNING: return LOG_WARNING;
250  case LOG_LEVEL_NOTICE: return LOG_NOTICE;
251  case LOG_LEVEL_INFO: return LOG_INFO;
252  case LOG_LEVEL_VERBOSE: return LOG_DEBUG; /* FIXME: Do we really want to conflate those levels? */
253  case LOG_LEVEL_DEBUG: return LOG_DEBUG;
254  default:
255  ProgrammingError("LogLevelToSyslogPriority: Unexpected log level %d",
256  level);
257  }
258 
259 }
260 
261 void LogToSystemLog(const char *msg, LogLevel level)
262 {
263  char logmsg[4096];
264  snprintf(logmsg, sizeof(logmsg), "CFEngine(%s) %s %s\n", AgentType, VPREFIX, msg);
265  syslog(LogLevelToSyslogPriority(level), "%s", logmsg);
266 }
267 #endif /* !__MINGW32__ */
268 
269 #ifndef __MINGW32__
270 const char *GetErrorStrFromCode(int error_code)
271 {
272  return strerror(error_code);
273 }
274 
275 const char *GetErrorStr(void)
276 {
277  return strerror(errno);
278 }
279 
280 #else
281 
282 const char *GetErrorStrFromCode(int error_code)
283 {
284  static char errbuf[CF_BUFSIZE];
285  int len;
286 
287  memset(errbuf, 0, sizeof(errbuf));
288 
289  if (FormatMessage(FORMAT_MESSAGE_FROM_SYSTEM, NULL, error_code,
290  MAKELANGID(LANG_ENGLISH, SUBLANG_ENGLISH_US), errbuf, CF_BUFSIZE, NULL))
291  {
292  // remove CRLF from end
293  len = strlen(errbuf);
294  errbuf[len - 2] = errbuf[len - 1] = '\0';
295  } else {
296  strcpy(errbuf, "Unknown error");
297  }
298 
299  return errbuf;
300 }
301 
302 const char *GetErrorStr(void)
303 {
304  return GetErrorStrFromCode(GetLastError());
305 }
306 #endif /* !__MINGW32__ */
307 
308 bool WouldLog(LogLevel level)
309 {
311 
312  bool log_to_console = (level <= lctx->report_level);
313  bool log_to_syslog = (level <= lctx->log_level &&
314  level < LOG_LEVEL_VERBOSE);
315  bool force_hook = (lctx->pctx &&
316  lctx->pctx->log_hook &&
317  lctx->pctx->force_hook_level >= level);
318 
319  return (log_to_console || log_to_syslog || force_hook);
320 }
321 
322 void VLog(LogLevel level, const char *fmt, va_list ap)
323 {
325 
326  bool log_to_console = ( level <= lctx->report_level );
327  bool log_to_syslog = ( level <= lctx->log_level &&
328  level < LOG_LEVEL_VERBOSE );
329  bool force_hook = ( lctx->pctx &&
330  lctx->pctx->log_hook &&
331  lctx->pctx->force_hook_level >= level );
332 
333  /* NEEDS TO BE IN SYNC WITH THE CONDITION IN WouldLog() ABOVE! */
334  if (!log_to_console && !log_to_syslog && !force_hook)
335  {
336  return; /* early return - save resources */
337  }
338 
339  char *msg = StringVFormat(fmt, ap);
340  char *hooked_msg = NULL;
341 
342  /* Remove ending EOLN. */
343  for (char *sp = msg; *sp != '\0'; sp++)
344  {
345  if (*sp == '\n' && *(sp+1) == '\0')
346  {
347  *sp = '\0';
348  break;
349  }
350  }
351 
352  if (lctx->pctx && lctx->pctx->log_hook)
353  {
354  hooked_msg = lctx->pctx->log_hook(lctx->pctx, level, msg);
355  }
356  else
357  {
358  hooked_msg = msg;
359  }
360 
361  if (log_to_console)
362  {
363  LogToConsole(hooked_msg, level, lctx->color);
364  }
365  if (log_to_syslog)
366  {
367  LogToSystemLog(hooked_msg, level);
368  }
369 
370  if (hooked_msg != msg)
371  {
372  free(hooked_msg);
373  }
374  free(msg);
375 }
376 
377 /**
378  * @brief Logs binary data in #buf, with unprintable bytes translated to '.'.
379  * Message is prefixed with #prefix.
380  * @param #buflen must be no more than CF_BUFSIZE
381  */
382 void LogRaw(LogLevel level, const char *prefix, const void *buf, size_t buflen)
383 {
384  if (buflen > CF_BUFSIZE)
385  {
387  buflen = CF_BUFSIZE;
388  }
389 
391  if (level <= lctx->report_level || level <= lctx->log_level)
392  {
393  const unsigned char *src = buf;
394  unsigned char dst[CF_BUFSIZE+1];
395  assert(buflen < sizeof(dst));
396  size_t i;
397  for (i = 0; i < buflen; i++)
398  {
399  dst[i] = isprint(src[i]) ? src[i] : '.';
400  }
401  assert(i < sizeof(dst));
402  dst[i] = '\0';
403 
404  /* And Log the translated buffer, which is now a valid string. */
405  Log(level, "%s%s", prefix, dst);
406  }
407 }
408 
409 void Log(LogLevel level, const char *fmt, ...)
410 {
411  va_list ap;
412  va_start(ap, fmt);
413  VLog(level, fmt, ap);
414  va_end(ap);
415 }
416 
417 
418 
420 static const char *log_modules[LOG_MOD_MAX] =
421 {
422  "",
423  "evalctx",
424  "expand",
425  "iterations",
426  "parser",
427  "vartable",
428  "vars",
429  "locks",
430  "ps",
431 };
432 
433 static enum LogModule LogModuleFromString(const char *s)
434 {
435  for (enum LogModule i = 0; i < LOG_MOD_MAX; i++)
436  {
437  if (strcmp(log_modules[i], s) == 0)
438  {
439  return i;
440  }
441  }
442 
443  return LOG_MOD_NONE;
444 }
445 
447 {
448  assert(mod < LOG_MOD_MAX);
449 
450  module_is_enabled[mod] = true;
451 }
452 
453 void LogModuleHelp(void)
454 {
455  printf("\n--log-modules accepts a comma separated list of one or more of the following:\n\n");
456  printf(" help\n");
457  printf(" all\n");
458  for (enum LogModule i = LOG_MOD_NONE + 1; i < LOG_MOD_MAX; i++)
459  {
460  printf(" %s\n", log_modules[i]);
461  }
462  printf("\n");
463 }
464 
465 /**
466  * Parse a string of modules, and enable the relevant DEBUG logging modules.
467  * Example strings:
468  *
469  * all : enables all debug modules
470  * help : enables nothing, but prints a help message
471  * iterctx : enables the "iterctx" debug logging module
472  * iterctx,vars: enables the 2 debug modules, "iterctx" and "vars"
473  *
474  * @NOTE modifies string #s but restores it before returning.
475  */
477 {
478  bool retval = true;
479 
480  const char *token = s;
481  char saved_sep = ','; /* any non-NULL value will do */
482  while (saved_sep != '\0' && retval != false)
483  {
484  char *next_token = strchrnul(token, ',');
485  saved_sep = *next_token;
486  *next_token = '\0'; /* modify parameter s */
487  size_t token_len = next_token - token;
488 
489  if (strcmp(token, "help") == 0)
490  {
491  LogModuleHelp();
492  retval = false; /* early exit */
493  }
494  else if (strcmp(token, "all") == 0)
495  {
496  for (enum LogModule j = LOG_MOD_NONE + 1; j < LOG_MOD_MAX; j++)
497  {
498  LogEnableModule(j);
499  }
500  }
501  else
502  {
503  enum LogModule mod = LogModuleFromString(token);
504 
505  assert(mod < LOG_MOD_MAX);
506  if (mod == LOG_MOD_NONE)
507  {
509  "Unknown debug logging module '%*s'",
510  (int) token_len, token);
511  }
512  else
513  {
514  LogEnableModule(mod);
515  }
516  }
517 
518 
519  *next_token = saved_sep; /* restore modified parameter s */
520  next_token++; /* bypass comma */
521  token = next_token;
522  }
523 
524  return retval;
525 }
526 
528 {
529  assert(mod > LOG_MOD_NONE);
530  assert(mod < LOG_MOD_MAX);
531 
532  if (module_is_enabled[mod])
533  {
534  return true;
535  }
536  else
537  {
538  return false;
539  }
540 }
541 
542 void LogDebug(enum LogModule mod, const char *fmt, ...)
543 {
544  assert(mod < LOG_MOD_MAX);
545 
546  /* Did we forget any entry in log_modules? */
547  nt_static_assert(sizeof(log_modules) / sizeof(log_modules[0]) == LOG_MOD_MAX);
548 
549  if (LogModuleEnabled(mod))
550  {
551  va_list ap;
552  va_start(ap, fmt);
553  VLog(LOG_LEVEL_DEBUG, fmt, ap);
554  va_end(ap);
555  /* VLog(LOG_LEVEL_DEBUG, "%s: ...", */
556  /* debug_modules_description[mod_order], ...); */
557  }
558 }
559 
560 
562 {
563  global_level = level;
564  LoggingPrivSetLevels(level, level);
565 }
566 
567 void LogSetGlobalLevelArgOrExit(const char *const arg)
568 {
569  LogLevel level = LogLevelFromString(arg);
570  if (level == LOG_LEVEL_NOTHING)
571  {
572  // This function is used as part of initializing the logging
573  // system. Using Log() can be considered incorrect, even though
574  // it may "work". Let's just print an error to stderr:
575  fprintf(stderr, "Invalid log level: '%s'\n", arg);
576  DoCleanupAndExit(1);
577  }
578  LogSetGlobalLevel(level);
579 }
580 
582 {
583  return global_level;
584 }
585 
586 void LoggingSetColor(bool enabled)
587 {
589  lctx->color = enabled;
590 }
591 
592 // byte_magnitude and byte_unit are used to print human readable byte counts
593 long byte_magnitude(long bytes)
594 {
595  const long Ki = 1024;
596  const long Mi = Ki * 1024;
597  const long Gi = Mi * 1024;
598 
599  if (bytes > 8 * Gi)
600  {
601  return bytes / Gi;
602  }
603  else if (bytes > 8 * Mi)
604  {
605  return bytes / Mi;
606  }
607  else if (bytes > 8 * Ki)
608  {
609  return bytes / Ki;
610  }
611  return bytes;
612 }
613 
614 // Use this with byte_magnitude
615 // Note that the cutoff is at 8x unit, because 3192 bytes is arguably more
616 // useful than 3KiB
617 const char *byte_unit(long bytes)
618 {
619  const long Ki = 1024;
620  const long Mi = Ki * 1024;
621  const long Gi = Mi * 1024;
622 
623  if (bytes > 8 * Gi)
624  {
625  return "GiB";
626  }
627  else if (bytes > 8 * Mi)
628  {
629  return "MiB";
630  }
631  else if (bytes > 8 * Ki)
632  {
633  return "KiB";
634  }
635  return "bytes";
636 }
void * xcalloc(size_t nmemb, size_t size)
Definition: alloc-mini.c:51
#define FREE_AND_NULL(ptr)
Definition: alloc.h:43
AgentType
Definition: cf3.defs.h:400
void free(void *)
void DoCleanupAndExit(int ret)
Definition: cleanup.c:57
#define debug_abort_if_reached()
#define nt_static_assert(x)
#define CF_BUFSIZE
Definition: definitions.h:50
int errno
#define NULL
Definition: getopt1.c:56
struct tm * localtime_r(const time_t *timep, struct tm *result)
LogLevel
Definition: log.h:30
void LogRaw(LogLevel level, const char *prefix, const void *buf, size_t buflen)
Logs binary data in #buf, with unprintable bytes translated to '.'. Message is prefixed with #prefix.
Definition: logging.c:382
const char * byte_unit(long bytes)
Definition: logging.c:617
void LoggingSetAgentType(const char *type)
Definition: logging.c:83
static bool TIMESTAMPS
Definition: logging.c:36
bool LogEnableModulesFromString(char *s)
Definition: logging.c:476
void VLog(LogLevel level, const char *fmt, va_list ap)
Definition: logging.c:322
void LoggingPrivSetContext(LoggingPrivContext *pctx)
Attaches context to logging for current thread.
Definition: logging.c:93
void LogSetGlobalLevelArgOrExit(const char *const arg)
Definition: logging.c:567
static bool module_is_enabled[LOG_MOD_MAX]
Definition: logging.c:419
void LoggingEnableTimestamps(bool enable)
Definition: logging.c:88
static enum LogModule LogModuleFromString(const char *s)
Definition: logging.c:433
const char * GetErrorStrFromCode(int error_code)
Definition: logging.c:270
void LoggingSetColor(bool enabled)
Definition: logging.c:586
static void LoggingInitializeOnce(void)
Definition: logging.c:43
void LogModuleHelp(void)
Definition: logging.c:453
LoggingContext * GetCurrentThreadContext(void)
Definition: logging.c:56
static const char * log_modules[LOG_MOD_MAX]
Definition: logging.c:420
long byte_magnitude(long bytes)
Definition: logging.c:593
void LogSetGlobalLevel(LogLevel level)
Definition: logging.c:561
LoggingPrivContext * LoggingPrivGetContext(void)
Retrieves logging context for current thread.
Definition: logging.c:99
static const char * LogLevelToColor(LogLevel level)
Definition: logging.c:175
char VPREFIX[1024]
Definition: logging.c:33
LogLevel LogLevelFromString(const char *const level)
Definition: logging.c:135
void LogDebug(enum LogModule mod, const char *fmt,...)
Definition: logging.c:542
static pthread_once_t log_context_init_once
Definition: logging.c:40
bool LoggingFormatTimestamp(char dest[64], size_t n, struct tm *timestamp)
Return the standard timestamp format used in logging.
Definition: logging.c:200
void LogEnableModule(enum LogModule mod)
Definition: logging.c:446
LogLevel LogGetGlobalLevel(void)
Definition: logging.c:581
static pthread_key_t log_context_key
Definition: logging.c:41
void LoggingFreeCurrentThreadContext(void)
Definition: logging.c:70
static LogLevel global_level
Definition: logging.c:38
void LoggingPrivSetLevels(LogLevel log_level, LogLevel report_level)
Set logging (syslog) and reporting (stdout) level for current thread.
Definition: logging.c:105
void LogToSystemLog(const char *msg, LogLevel level)
Definition: logging.c:261
bool LogModuleEnabled(enum LogModule mod)
Definition: logging.c:527
static int LogLevelToSyslogPriority(LogLevel level)
Definition: logging.c:243
bool WouldLog(LogLevel level)
Definition: logging.c:308
const char * GetErrorStr(void)
Definition: logging.c:275
static void LogToConsole(const char *msg, LogLevel level, bool color)
Definition: logging.c:210
void Log(LogLevel level, const char *fmt,...)
Definition: logging.c:409
const char * LogLevelToString(LogLevel level)
Definition: logging.c:112
LogModule
Definition: logging.h:56
@ LOG_MOD_NONE
Definition: logging.h:57
@ LOG_MOD_MAX
Definition: logging.h:66
@ LOG_LEVEL_ERR
Definition: logging.h:42
@ LOG_LEVEL_NOTICE
Definition: logging.h:44
@ LOG_LEVEL_DEBUG
Definition: logging.h:47
@ LOG_LEVEL_WARNING
Definition: logging.h:43
@ LOG_LEVEL_CRIT
Definition: logging.h:41
@ LOG_LEVEL_VERBOSE
Definition: logging.h:46
@ LOG_LEVEL_NOTHING
Definition: logging.h:40
@ LOG_LEVEL_INFO
Definition: logging.h:45
#define ProgrammingError(...)
Definition: misc_lib.h:33
char * strchrnul(const char *s, int c)
Definition: strchrnul.c:9
char * strerror(int err)
Definition: strerror.c:35
bool StringEqualN_IgnoreCase(const char *const a, const char *const b, const size_t n)
Definition: string_lib.c:301
char * StringVFormat(const char *fmt, va_list ap)
Format string like vsprintf and return formatted string allocated on heap as a return value.
Definition: string_lib.c:37
int SafeStringLength(const char *str)
Definition: string_lib.c:196
size_t strlcpy(char *dst, const char *src, size_t siz)
Definition: strlcpy.c:34
bool color
Definition: logging.h:77
LoggingPrivContext * pctx
Definition: logging.h:79
LogLevel log_level
Definition: logging.h:75
LogLevel report_level
Definition: logging.h:76
LogLevel force_hook_level
Definition: logging_priv.h:50
LoggingPrivLogHook log_hook
Definition: logging_priv.h:38