lib/common/logging.c

/* */
This source file includes following definitions.
crm_glib_handler
crm_trigger_blackbox
crm_log_deinit
set_format_string
logfile_disabled
chown_logfile
chmod_logfile
set_logfile_permissions
enable_logfile
disable_logfile
setenv_logfile
pcmk__add_logfile
pcmk__add_logfiles
blackbox_logger
crm_control_blackbox
crm_enable_blackbox
crm_disable_blackbox
crm_write_blackbox
crm_quark_to_string
crm_log_filter_source
crm_log_filter
crm_is_callsite_active
crm_update_callsites
crm_tracing_enabled
crm_priority2int
set_identity
crm_log_preinit
crm_log_init
set_crm_log_level
crm_enable_stderr
crm_bump_log_level
get_crm_log_level
crm_log_args
crm_log_output_fn
pcmk__cli_init_logging
pcmk_log_xml_impl
pcmk__free_common_logger
crm_log_cli_init
crm_add_logfile
   1 /*
   2  * Copyright 2004-2023 the Pacemaker project contributors
   3  *
   4  * The version control history for this file may have further details.
   5  *
   6  * This source code is licensed under the GNU Lesser General Public License
   7  * version 2.1 or later (LGPLv2.1+) WITHOUT ANY WARRANTY.
   8  */
   9 
  10 #include <crm_internal.h>
  11 
  12 #include <sys/param.h>
  13 #include <sys/types.h>
  14 #include <sys/wait.h>
  15 #include <sys/stat.h>
  16 #include <sys/utsname.h>
  17 
  18 #include <stdio.h>
  19 #include <unistd.h>
  20 #include <string.h>
  21 #include <stdlib.h>
  22 #include <limits.h>
  23 #include <ctype.h>
  24 #include <pwd.h>
  25 #include <grp.h>
  26 #include <time.h>
  27 #include <libgen.h>
  28 #include <signal.h>
  29 #include <bzlib.h>
  30 
  31 #include <qb/qbdefs.h>
  32 
  33 #include <crm/crm.h>
  34 #include <crm/common/mainloop.h>
  35 
  36 // Use high-resolution (millisecond) timestamps if libqb supports them
  37 #ifdef QB_FEATURE_LOG_HIRES_TIMESTAMPS
  38 #define TIMESTAMP_FORMAT_SPEC "%%T"
  39 typedef struct timespec *log_time_t;
  40 #else
  41 #define TIMESTAMP_FORMAT_SPEC "%%t"
  42 typedef time_t log_time_t;
  43 #endif
  44 
  45 unsigned int crm_log_level = LOG_INFO;
  46 unsigned int crm_trace_nonlog = 0;
  47 bool pcmk__is_daemon = false;
  48 char *pcmk__our_nodename = NULL;
  49 
  50 static unsigned int crm_log_priority = LOG_NOTICE;
  51 static GLogFunc glib_log_default = NULL;
  52 static pcmk__output_t *logger_out = NULL;
  53 
  54 static gboolean crm_tracing_enabled(void);
  55 
  56 static void
  57 crm_glib_handler(const gchar * log_domain, GLogLevelFlags flags, const gchar * message,
     /*  */
  58                  gpointer user_data)
  59 {
  60     int log_level = LOG_WARNING;
  61     GLogLevelFlags msg_level = (flags & G_LOG_LEVEL_MASK);
  62     static struct qb_log_callsite *glib_cs = NULL;
  63 
  64     if (glib_cs == NULL) {
  65         glib_cs = qb_log_callsite_get(__func__, __FILE__, "glib-handler",
  66                                       LOG_DEBUG, __LINE__, crm_trace_nonlog);
  67     }
  68 
  69     switch (msg_level) {
  70         case G_LOG_LEVEL_CRITICAL:
  71             log_level = LOG_CRIT;
  72 
  73             if (!crm_is_callsite_active(glib_cs, LOG_DEBUG, crm_trace_nonlog)) {
  74                 /* log and record how we got here */
  75                 crm_abort(__FILE__, __func__, __LINE__, message, TRUE, TRUE);
  76             }
  77             break;
  78 
  79         case G_LOG_LEVEL_ERROR:
  80             log_level = LOG_ERR;
  81             break;
  82         case G_LOG_LEVEL_MESSAGE:
  83             log_level = LOG_NOTICE;
  84             break;
  85         case G_LOG_LEVEL_INFO:
  86             log_level = LOG_INFO;
  87             break;
  88         case G_LOG_LEVEL_DEBUG:
  89             log_level = LOG_DEBUG;
  90             break;
  91 
  92         case G_LOG_LEVEL_WARNING:
  93         case G_LOG_FLAG_RECURSION:
  94         case G_LOG_FLAG_FATAL:
  95         case G_LOG_LEVEL_MASK:
  96             log_level = LOG_WARNING;
  97             break;
  98     }
  99 
 100     do_crm_log(log_level, "%s: %s", log_domain, message);
 101 }
 102 
 103 #ifndef NAME_MAX
 104 #  define NAME_MAX 256
 105 #endif
 106 
 107 /*!
 108  * \internal
 109  * \brief Write out a blackbox (enabling blackboxes if needed)
 110  *
 111  * \param[in] nsig  Signal number that was received
 112  *
 113  * \note This is a true signal handler, and so must be async-safe.
 114  */
 115 static void
 116 crm_trigger_blackbox(int nsig)
     /*  */
 117 {
 118     if(nsig == SIGTRAP) {
 119         /* Turn it on if it wasn't already */
 120         crm_enable_blackbox(nsig);
 121     }
 122     crm_write_blackbox(nsig, NULL);
 123 }
 124 
 125 void
 126 crm_log_deinit(void)
     /*  */
 127 {
 128     if (glib_log_default != NULL) {
 129         g_log_set_default_handler(glib_log_default, NULL);
 130     }
 131 }
 132 
 133 #define FMT_MAX 256
 134 
 135 /*!
 136  * \internal
 137  * \brief Set the log format string based on the passed-in method
 138  *
 139  * \param[in] method        The detail level of the log output
 140  * \param[in] daemon        The daemon ID included in error messages
 141  * \param[in] use_pid       Cached result of getpid() call, for efficiency
 142  * \param[in] use_nodename  Cached result of uname() call, for efficiency
 143  *
 144  */
 145 
 146 /* XXX __attribute__((nonnull)) for use_nodename parameter */
 147 static void
 148 set_format_string(int method, const char *daemon, pid_t use_pid,
     /*  */
 149                   const char *use_nodename)
 150 {
 151     if (method == QB_LOG_SYSLOG) {
 152         // The system log gets a simplified, user-friendly format
 153         crm_extended_logging(method, QB_FALSE);
 154         qb_log_format_set(method, "%g %p: %b");
 155 
 156     } else {
 157         // Everything else gets more detail, for advanced troubleshooting
 158 
 159         int offset = 0;
 160         char fmt[FMT_MAX];
 161 
 162         if (method > QB_LOG_STDERR) {
 163             // If logging to file, prefix with timestamp, node name, daemon ID
 164             offset += snprintf(fmt + offset, FMT_MAX - offset,
 165                                TIMESTAMP_FORMAT_SPEC " %s %-20s[%lu] ",
 166                                 use_nodename, daemon, (unsigned long) use_pid);
 167         }
 168 
 169         // Add function name (in parentheses)
 170         offset += snprintf(fmt + offset, FMT_MAX - offset, "(%%n");
 171         if (crm_tracing_enabled()) {
 172             // When tracing, add file and line number
 173             offset += snprintf(fmt + offset, FMT_MAX - offset, "@%%f:%%l");
 174         }
 175         offset += snprintf(fmt + offset, FMT_MAX - offset, ")");
 176 
 177         // Add tag (if any), severity, and actual message
 178         offset += snprintf(fmt + offset, FMT_MAX - offset, " %%g\t%%p: %%b");
 179 
 180         CRM_LOG_ASSERT(offset > 0);
 181         qb_log_format_set(method, fmt);
 182     }
 183 }
 184 
 185 #define DEFAULT_LOG_FILE CRM_LOG_DIR "/pacemaker.log"
 186 
 187 static bool
 188 logfile_disabled(const char *filename)
     /*  */
 189 {
 190     return pcmk__str_eq(filename, PCMK__VALUE_NONE, pcmk__str_casei)
 191            || pcmk__str_eq(filename, "/dev/null", pcmk__str_none);
 192 }
 193 
 194 /*!
 195  * \internal
 196  * \brief Fix log file ownership if group is wrong or doesn't have access
 197  *
 198  * \param[in] filename  Log file name (for logging only)
 199  * \param[in] logfd     Log file descriptor
 200  *
 201  * \return Standard Pacemaker return code
 202  */
 203 static int
 204 chown_logfile(const char *filename, int logfd)
     /*  */
 205 {
 206     uid_t pcmk_uid = 0;
 207     gid_t pcmk_gid = 0;
 208     struct stat st;
 209     int rc;
 210 
 211     // Get the log file's current ownership and permissions
 212     if (fstat(logfd, &st) < 0) {
 213         return errno;
 214     }
 215 
 216     // Any other errors don't prevent file from being used as log
 217 
 218     rc = pcmk_daemon_user(&pcmk_uid, &pcmk_gid);
 219     if (rc != pcmk_ok) {
 220         rc = pcmk_legacy2rc(rc);
 221         crm_warn("Not changing '%s' ownership because user information "
 222                  "unavailable: %s", filename, pcmk_rc_str(rc));
 223         return pcmk_rc_ok;
 224     }
 225     if ((st.st_gid == pcmk_gid)
 226         && ((st.st_mode & S_IRWXG) == (S_IRGRP|S_IWGRP))) {
 227         return pcmk_rc_ok;
 228     }
 229     if (fchown(logfd, pcmk_uid, pcmk_gid) < 0) {
 230         crm_warn("Couldn't change '%s' ownership to user %s gid %d: %s",
 231              filename, CRM_DAEMON_USER, pcmk_gid, strerror(errno));
 232     }
 233     return pcmk_rc_ok;
 234 }
 235 
 236 // Reset log file permissions (using environment variable if set)
 237 static void
 238 chmod_logfile(const char *filename, int logfd)
     /*  */
 239 {
 240     const char *modestr = getenv("PCMK_logfile_mode");
 241     mode_t filemode = S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP;
 242 
 243     if (modestr != NULL) {
 244         long filemode_l = strtol(modestr, NULL, 8);
 245 
 246         if ((filemode_l != LONG_MIN) && (filemode_l != LONG_MAX)) {
 247             filemode = (mode_t) filemode_l;
 248         }
 249     }
 250     if ((filemode != 0) && (fchmod(logfd, filemode) < 0)) {
 251         crm_warn("Couldn't change '%s' mode to %04o: %s",
 252                  filename, filemode, strerror(errno));
 253     }
 254 }
 255 
 256 // If we're root, correct a log file's permissions if needed
 257 static int
 258 set_logfile_permissions(const char *filename, FILE *logfile)
     /*  */
 259 {
 260     if (geteuid() == 0) {
 261         int logfd = fileno(logfile);
 262         int rc = chown_logfile(filename, logfd);
 263 
 264         if (rc != pcmk_rc_ok) {
 265             return rc;
 266         }
 267         chmod_logfile(filename, logfd);
 268     }
 269     return pcmk_rc_ok;
 270 }
 271 
 272 // Enable libqb logging to a new log file
 273 static void
 274 enable_logfile(int fd)
     /*  */
 275 {
 276     qb_log_ctl(fd, QB_LOG_CONF_ENABLED, QB_TRUE);
 277 #if 0
 278     qb_log_ctl(fd, QB_LOG_CONF_FILE_SYNC, 1); // Turn on synchronous writes
 279 #endif
 280 
 281 #ifdef HAVE_qb_log_conf_QB_LOG_CONF_MAX_LINE_LEN
 282     // Longer than default, for logging long XML lines
 283     qb_log_ctl(fd, QB_LOG_CONF_MAX_LINE_LEN, 800);
 284 #endif
 285 
 286     crm_update_callsites();
 287 }
 288 
 289 static inline void
 290 disable_logfile(int fd)
     /*  */
 291 {
 292     qb_log_ctl(fd, QB_LOG_CONF_ENABLED, QB_FALSE);
 293 }
 294 
 295 static void
 296 setenv_logfile(const char *filename)
     /*  */
 297 {
 298     // Some resource agents will log only if environment variable is set
 299     if (pcmk__env_option(PCMK__ENV_LOGFILE) == NULL) {
 300         pcmk__set_env_option(PCMK__ENV_LOGFILE, filename);
 301     }
 302 }
 303 
 304 /*!
 305  * \brief Add a file to be used as a Pacemaker detail log
 306  *
 307  * \param[in] filename  Name of log file to use
 308  *
 309  * \return Standard Pacemaker return code
 310  */
 311 int
 312 pcmk__add_logfile(const char *filename)
     /*  */
 313 {
 314     /* No log messages from this function will be logged to the new log!
 315      * If another target such as syslog has already been added, the messages
 316      * should show up there.
 317      */
 318 
 319     int fd = 0;
 320     int rc = pcmk_rc_ok;
 321     FILE *logfile = NULL;
 322     bool is_default = false;
 323 
 324     static int default_fd = -1;
 325     static bool have_logfile = false;
 326 
 327     // Use default if caller didn't specify (and we don't already have one)
 328     if (filename == NULL) {
 329         if (have_logfile) {
 330             return pcmk_rc_ok;
 331         }
 332         filename = DEFAULT_LOG_FILE;
 333     }
 334 
 335     // If the user doesn't want logging, we're done
 336     if (logfile_disabled(filename)) {
 337         return pcmk_rc_ok;
 338     }
 339 
 340     // If the caller wants the default and we already have it, we're done
 341     is_default = pcmk__str_eq(filename, DEFAULT_LOG_FILE, pcmk__str_none);
 342     if (is_default && (default_fd >= 0)) {
 343         return pcmk_rc_ok;
 344     }
 345 
 346     // Check whether we have write access to the file
 347     logfile = fopen(filename, "a");
 348     if (logfile == NULL) {
 349         rc = errno;
 350         crm_warn("Logging to '%s' is disabled: %s " CRM_XS " uid=%u gid=%u",
 351                  filename, strerror(rc), geteuid(), getegid());
 352         return rc;
 353     }
 354 
 355     rc = set_logfile_permissions(filename, logfile);
 356     if (rc != pcmk_rc_ok) {
 357         crm_warn("Logging to '%s' is disabled: %s " CRM_XS " permissions",
 358                  filename, strerror(rc));
 359         fclose(logfile);
 360         return rc;
 361     }
 362 
 363     // Close and reopen as libqb logging target
 364     fclose(logfile);
 365     fd = qb_log_file_open(filename);
 366     if (fd < 0) {
 367         crm_warn("Logging to '%s' is disabled: %s " CRM_XS " qb_log_file_open",
 368                  filename, strerror(-fd));
 369         return -fd; // == +errno
 370     }
 371 
 372     if (is_default) {
 373         default_fd = fd;
 374         setenv_logfile(filename);
 375 
 376     } else if (default_fd >= 0) {
 377         crm_notice("Switching logging to %s", filename);
 378         disable_logfile(default_fd);
 379     }
 380 
 381     crm_notice("Additional logging available in %s", filename);
 382     enable_logfile(fd);
 383     have_logfile = true;
 384     return pcmk_rc_ok;
 385 }
 386 
 387 /*!
 388  * \brief Add multiple additional log files
 389  *
 390  * \param[in] log_files  Array of log files to add
 391  * \param[in] out        Output object to use for error reporting
 392  *
 393  * \return Standard Pacemaker return code
 394  */
 395 void
 396 pcmk__add_logfiles(gchar **log_files, pcmk__output_t *out)
     /*  */
 397 {
 398     if (log_files == NULL) {
 399         return;
 400     }
 401 
 402     for (gchar **fname = log_files; *fname != NULL; fname++) {
 403         int rc = pcmk__add_logfile(*fname);
 404 
 405         if (rc != pcmk_rc_ok) {
 406             out->err(out, "Logging to %s is disabled: %s",
 407                      *fname, pcmk_rc_str(rc));
 408         }
 409     }
 410 }
 411 
 412 static int blackbox_trigger = 0;
 413 static volatile char *blackbox_file_prefix = NULL;
 414 
 415 static void
 416 blackbox_logger(int32_t t, struct qb_log_callsite *cs, log_time_t timestamp,
     /*  */
 417                 const char *msg)
 418 {
 419     if(cs && cs->priority < LOG_ERR) {
 420         crm_write_blackbox(SIGTRAP, cs); /* Bypass the over-dumping logic */
 421     } else {
 422         crm_write_blackbox(0, cs);
 423     }
 424 }
 425 
 426 static void
 427 crm_control_blackbox(int nsig, bool enable)
     /*  */
 428 {
 429     int lpc = 0;
 430 
 431     if (blackbox_file_prefix == NULL) {
 432         pid_t pid = getpid();
 433 
 434         blackbox_file_prefix = crm_strdup_printf("%s/%s-%lu",
 435                                                  CRM_BLACKBOX_DIR,
 436                                                  crm_system_name,
 437                                                  (unsigned long) pid);
 438     }
 439 
 440     if (enable && qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) {
 441         qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 5 * 1024 * 1024); /* Any size change drops existing entries */
 442         qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE);      /* Setting the size seems to disable it */
 443 
 444         /* Enable synchronous logging */
 445         for (lpc = QB_LOG_BLACKBOX; lpc < QB_LOG_TARGET_MAX; lpc++) {
 446             qb_log_ctl(lpc, QB_LOG_CONF_FILE_SYNC, QB_TRUE);
 447         }
 448 
 449         crm_notice("Initiated blackbox recorder: %s", blackbox_file_prefix);
 450 
 451         /* Save to disk on abnormal termination */
 452         crm_signal_handler(SIGSEGV, crm_trigger_blackbox);
 453         crm_signal_handler(SIGABRT, crm_trigger_blackbox);
 454         crm_signal_handler(SIGILL,  crm_trigger_blackbox);
 455         crm_signal_handler(SIGBUS,  crm_trigger_blackbox);
 456         crm_signal_handler(SIGFPE,  crm_trigger_blackbox);
 457 
 458         crm_update_callsites();
 459 
 460         blackbox_trigger = qb_log_custom_open(blackbox_logger, NULL, NULL, NULL);
 461         qb_log_ctl(blackbox_trigger, QB_LOG_CONF_ENABLED, QB_TRUE);
 462         crm_trace("Trigger: %d is %d %d", blackbox_trigger,
 463                   qb_log_ctl(blackbox_trigger, QB_LOG_CONF_STATE_GET, 0), QB_LOG_STATE_ENABLED);
 464 
 465         crm_update_callsites();
 466 
 467     } else if (!enable && qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0) == QB_LOG_STATE_ENABLED) {
 468         qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE);
 469 
 470         /* Disable synchronous logging again when the blackbox is disabled */
 471         for (lpc = QB_LOG_BLACKBOX; lpc < QB_LOG_TARGET_MAX; lpc++) {
 472             qb_log_ctl(lpc, QB_LOG_CONF_FILE_SYNC, QB_FALSE);
 473         }
 474     }
 475 }
 476 
 477 void
 478 crm_enable_blackbox(int nsig)
     /*  */
 479 {
 480     crm_control_blackbox(nsig, TRUE);
 481 }
 482 
 483 void
 484 crm_disable_blackbox(int nsig)
     /*  */
 485 {
 486     crm_control_blackbox(nsig, FALSE);
 487 }
 488 
 489 /*!
 490  * \internal
 491  * \brief Write out a blackbox, if blackboxes are enabled
 492  *
 493  * \param[in] nsig  Signal that was received
 494  * \param[in] cs    libqb callsite
 495  *
 496  * \note This may be called via a true signal handler and so must be async-safe.
 497  * @TODO actually make this async-safe
 498  */
 499 void
 500 crm_write_blackbox(int nsig, const struct qb_log_callsite *cs)
     /*  */
 501 {
 502     static volatile int counter = 1;
 503     static volatile time_t last = 0;
 504 
 505     char buffer[NAME_MAX];
 506     time_t now = time(NULL);
 507 
 508     if (blackbox_file_prefix == NULL) {
 509         return;
 510     }
 511 
 512     switch (nsig) {
 513         case 0:
 514         case SIGTRAP:
 515             /* The graceful case - such as assertion failure or user request */
 516 
 517             if (nsig == 0 && now == last) {
 518                 /* Prevent over-dumping */
 519                 return;
 520             }
 521 
 522             snprintf(buffer, NAME_MAX, "%s.%d", blackbox_file_prefix, counter++);
 523             if (nsig == SIGTRAP) {
 524                 crm_notice("Blackbox dump requested, please see %s for contents", buffer);
 525 
 526             } else if (cs) {
 527                 syslog(LOG_NOTICE,
 528                        "Problem detected at %s:%d (%s), please see %s for additional details",
 529                        cs->function, cs->lineno, cs->filename, buffer);
 530             } else {
 531                 crm_notice("Problem detected, please see %s for additional details", buffer);
 532             }
 533 
 534             last = now;
 535             qb_log_blackbox_write_to_file(buffer);
 536 
 537             /* Flush the existing contents
 538              * A size change would also work
 539              */
 540             qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE);
 541             qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE);
 542             break;
 543 
 544         default:
 545             /* Do as little as possible, just try to get what we have out
 546              * We logged the filename when the blackbox was enabled
 547              */
 548             crm_signal_handler(nsig, SIG_DFL);
 549             qb_log_blackbox_write_to_file((const char *)blackbox_file_prefix);
 550             qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE);
 551             raise(nsig);
 552             break;
 553     }
 554 }
 555 
 556 static const char *
 557 crm_quark_to_string(uint32_t tag)
     /*  */
 558 {
 559     const char *text = g_quark_to_string(tag);
 560 
 561     if (text) {
 562         return text;
 563     }
 564     return "";
 565 }
 566 
 567 static void
 568 crm_log_filter_source(int source, const char *trace_files, const char *trace_fns,
     /*  */
 569                       const char *trace_fmts, const char *trace_tags, const char *trace_blackbox,
 570                       struct qb_log_callsite *cs)
 571 {
 572     if (qb_log_ctl(source, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) {
 573         return;
 574     } else if (cs->tags != crm_trace_nonlog && source == QB_LOG_BLACKBOX) {
 575         /* Blackbox gets everything if enabled */
 576         qb_bit_set(cs->targets, source);
 577 
 578     } else if (source == blackbox_trigger && blackbox_trigger > 0) {
 579         /* Should this log message result in the blackbox being dumped */
 580         if (cs->priority <= LOG_ERR) {
 581             qb_bit_set(cs->targets, source);
 582 
 583         } else if (trace_blackbox) {
 584             char *key = crm_strdup_printf("%s:%d", cs->function, cs->lineno);
 585 
 586             if (strstr(trace_blackbox, key) != NULL) {
 587                 qb_bit_set(cs->targets, source);
 588             }
 589             free(key);
 590         }
 591 
 592     } else if (source == QB_LOG_SYSLOG) {       /* No tracing to syslog */
 593         if (cs->priority <= crm_log_priority && cs->priority <= crm_log_level) {
 594             qb_bit_set(cs->targets, source);
 595         }
 596         /* Log file tracing options... */
 597     } else if (cs->priority <= crm_log_level) {
 598         qb_bit_set(cs->targets, source);
 599     } else if (trace_files && strstr(trace_files, cs->filename) != NULL) {
 600         qb_bit_set(cs->targets, source);
 601     } else if (trace_fns && strstr(trace_fns, cs->function) != NULL) {
 602         qb_bit_set(cs->targets, source);
 603     } else if (trace_fmts && strstr(trace_fmts, cs->format) != NULL) {
 604         qb_bit_set(cs->targets, source);
 605     } else if (trace_tags
 606                && cs->tags != 0
 607                && cs->tags != crm_trace_nonlog && g_quark_to_string(cs->tags) != NULL) {
 608         qb_bit_set(cs->targets, source);
 609     }
 610 }
 611 
 612 static void
 613 crm_log_filter(struct qb_log_callsite *cs)
     /*  */
 614 {
 615     int lpc = 0;
 616     static int need_init = 1;
 617     static const char *trace_fns = NULL;
 618     static const char *trace_tags = NULL;
 619     static const char *trace_fmts = NULL;
 620     static const char *trace_files = NULL;
 621     static const char *trace_blackbox = NULL;
 622 
 623     if (need_init) {
 624         need_init = 0;
 625         trace_fns = getenv("PCMK_trace_functions");
 626         trace_fmts = getenv("PCMK_trace_formats");
 627         trace_tags = getenv("PCMK_trace_tags");
 628         trace_files = getenv("PCMK_trace_files");
 629         trace_blackbox = getenv("PCMK_trace_blackbox");
 630 
 631         if (trace_tags != NULL) {
 632             uint32_t tag;
 633             char token[500];
 634             const char *offset = NULL;
 635             const char *next = trace_tags;
 636 
 637             do {
 638                 offset = next;
 639                 next = strchrnul(offset, ',');
 640                 snprintf(token, sizeof(token), "%.*s", (int)(next - offset), offset);
 641 
 642                 tag = g_quark_from_string(token);
 643                 crm_info("Created GQuark %u from token '%s' in '%s'", tag, token, trace_tags);
 644 
 645                 if (next[0] != 0) {
 646                     next++;
 647                 }
 648 
 649             } while (next != NULL && next[0] != 0);
 650         }
 651     }
 652 
 653     cs->targets = 0;            /* Reset then find targets to enable */
 654     for (lpc = QB_LOG_SYSLOG; lpc < QB_LOG_TARGET_MAX; lpc++) {
 655         crm_log_filter_source(lpc, trace_files, trace_fns, trace_fmts, trace_tags, trace_blackbox,
 656                               cs);
 657     }
 658 }
 659 
 660 gboolean
 661 crm_is_callsite_active(struct qb_log_callsite *cs, uint8_t level, uint32_t tags)
     /*  */
 662 {
 663     gboolean refilter = FALSE;
 664 
 665     if (cs == NULL) {
 666         return FALSE;
 667     }
 668 
 669     if (cs->priority != level) {
 670         cs->priority = level;
 671         refilter = TRUE;
 672     }
 673 
 674     if (cs->tags != tags) {
 675         cs->tags = tags;
 676         refilter = TRUE;
 677     }
 678 
 679     if (refilter) {
 680         crm_log_filter(cs);
 681     }
 682 
 683     if (cs->targets == 0) {
 684         return FALSE;
 685     }
 686     return TRUE;
 687 }
 688 
 689 void
 690 crm_update_callsites(void)
     /*  */
 691 {
 692     static gboolean log = TRUE;
 693 
 694     if (log) {
 695         log = FALSE;
 696         crm_debug
 697             ("Enabling callsites based on priority=%d, files=%s, functions=%s, formats=%s, tags=%s",
 698              crm_log_level, getenv("PCMK_trace_files"), getenv("PCMK_trace_functions"),
 699              getenv("PCMK_trace_formats"), getenv("PCMK_trace_tags"));
 700     }
 701     qb_log_filter_fn_set(crm_log_filter);
 702 }
 703 
 704 static gboolean
 705 crm_tracing_enabled(void)
     /*  */
 706 {
 707     if (crm_log_level == LOG_TRACE) {
 708         return TRUE;
 709     } else if (getenv("PCMK_trace_files") || getenv("PCMK_trace_functions")
 710                || getenv("PCMK_trace_formats") || getenv("PCMK_trace_tags")) {
 711         return TRUE;
 712     }
 713     return FALSE;
 714 }
 715 
 716 static int
 717 crm_priority2int(const char *name)
     /*  */
 718 {
 719     struct syslog_names {
 720         const char *name;
 721         int priority;
 722     };
 723     static struct syslog_names p_names[] = {
 724         {"emerg", LOG_EMERG},
 725         {"alert", LOG_ALERT},
 726         {"crit", LOG_CRIT},
 727         {"error", LOG_ERR},
 728         {"warning", LOG_WARNING},
 729         {"notice", LOG_NOTICE},
 730         {"info", LOG_INFO},
 731         {"debug", LOG_DEBUG},
 732         {NULL, -1}
 733     };
 734     int lpc;
 735 
 736     for (lpc = 0; name != NULL && p_names[lpc].name != NULL; lpc++) {
 737         if (pcmk__str_eq(p_names[lpc].name, name, pcmk__str_none)) {
 738             return p_names[lpc].priority;
 739         }
 740     }
 741     return crm_log_priority;
 742 }
 743 
 744 
 745 /*!
 746  * \internal
 747  * \brief Set the identifier for the current process
 748  *
 749  * If the identifier crm_system_name is not already set, then it is set as follows:
 750  * - it is passed to the function via the "entity" parameter, or
 751  * - it is derived from the executable name
 752  *
 753  * The identifier can be used in logs, IPC, and more.
 754  *
 755  * This method also sets the PCMK_service environment variable.
 756  *
 757  * \param[in] entity  If not NULL, will be assigned to the identifier
 758  * \param[in] argc    The number of command line parameters
 759  * \param[in] argv    The command line parameter values
 760  */
 761 static void
 762 set_identity(const char *entity, int argc, char *const *argv)
     /*  */
 763 {
 764     if (crm_system_name != NULL) {
 765         return; // Already set, don't overwrite
 766     }
 767 
 768     if (entity != NULL) {
 769         crm_system_name = strdup(entity);
 770 
 771     } else if ((argc > 0) && (argv != NULL)) {
 772         char *mutable = strdup(argv[0]);
 773         char *modified = basename(mutable);
 774 
 775         if (strstr(modified, "lt-") == modified) {
 776             modified += 3;
 777         }
 778         crm_system_name = strdup(modified);
 779         free(mutable);
 780 
 781     } else {
 782         crm_system_name = strdup("Unknown");
 783     }
 784 
 785     CRM_ASSERT(crm_system_name != NULL);
 786 
 787     setenv("PCMK_service", crm_system_name, 1);
 788 }
 789 
 790 void
 791 crm_log_preinit(const char *entity, int argc, char *const *argv)
     /*  */
 792 {
 793     /* Configure libqb logging with nothing turned on */
 794 
 795     struct utsname res;
 796     int lpc = 0;
 797     int32_t qb_facility = 0;
 798     pid_t pid = getpid();
 799     const char *nodename = "localhost";
 800     static bool have_logging = false;
 801 
 802     if (have_logging) {
 803         return;
 804     }
 805 
 806     have_logging = true;
 807 
 808     crm_xml_init(); /* Sets buffer allocation strategy */
 809 
 810     if (crm_trace_nonlog == 0) {
 811         crm_trace_nonlog = g_quark_from_static_string("Pacemaker non-logging tracepoint");
 812     }
 813 
 814     umask(S_IWGRP | S_IWOTH | S_IROTH);
 815 
 816     /* Redirect messages from glib functions to our handler */
 817     glib_log_default = g_log_set_default_handler(crm_glib_handler, NULL);
 818 
 819     /* and for good measure... - this enum is a bit field (!) */
 820     g_log_set_always_fatal((GLogLevelFlags) 0); /*value out of range */
 821 
 822     /* Set crm_system_name, which is used as the logging name. It may also
 823      * be used for other purposes such as an IPC client name.
 824      */
 825     set_identity(entity, argc, argv);
 826 
 827     qb_facility = qb_log_facility2int("local0");
 828     qb_log_init(crm_system_name, qb_facility, LOG_ERR);
 829     crm_log_level = LOG_CRIT;
 830 
 831     /* Nuke any syslog activity until it's asked for */
 832     qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
 833 #ifdef HAVE_qb_log_conf_QB_LOG_CONF_MAX_LINE_LEN
 834     // Shorter than default, generous for what we *should* send to syslog
 835     qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_MAX_LINE_LEN, 256);
 836 #endif
 837     if (uname(memset(&res, 0, sizeof(res))) == 0 && *res.nodename != '\0') {
 838         nodename = res.nodename;
 839     }
 840 
 841     /* Set format strings and disable threading
 842      * Pacemaker and threads do not mix well (due to the amount of forking)
 843      */
 844     qb_log_tags_stringify_fn_set(crm_quark_to_string);
 845     for (lpc = QB_LOG_SYSLOG; lpc < QB_LOG_TARGET_MAX; lpc++) {
 846         qb_log_ctl(lpc, QB_LOG_CONF_THREADED, QB_FALSE);
 847 #ifdef HAVE_qb_log_conf_QB_LOG_CONF_ELLIPSIS
 848         // End truncated lines with '...'
 849         qb_log_ctl(lpc, QB_LOG_CONF_ELLIPSIS, QB_TRUE);
 850 #endif
 851         set_format_string(lpc, crm_system_name, pid, nodename);
 852     }
 853 
 854 #ifdef ENABLE_NLS
 855     /* Enable translations (experimental). Currently we only have a few
 856      * proof-of-concept translations for some option help. The goal would be to
 857      * offer translations for option help and man pages rather than logs or
 858      * documentation, to reduce the burden of maintaining them.
 859      */
 860 
 861     // Load locale information for the local host from the environment
 862     setlocale(LC_ALL, "");
 863 
 864     // Tell gettext where to find Pacemaker message catalogs
 865     CRM_ASSERT(bindtextdomain(PACKAGE, PCMK__LOCALE_DIR) != NULL);
 866 
 867     // Tell gettext to use the Pacemaker message catalogs
 868     CRM_ASSERT(textdomain(PACKAGE) != NULL);
 869 
 870     // Tell gettext that the translated strings are stored in UTF-8
 871     bind_textdomain_codeset(PACKAGE, "UTF-8");
 872 #endif
 873 }
 874 
 875 gboolean
 876 crm_log_init(const char *entity, uint8_t level, gboolean daemon, gboolean to_stderr,
     /*  */
 877              int argc, char **argv, gboolean quiet)
 878 {
 879     const char *syslog_priority = NULL;
 880     const char *facility = pcmk__env_option(PCMK__ENV_LOGFACILITY);
 881     const char *f_copy = facility;
 882 
 883     pcmk__is_daemon = daemon;
 884     crm_log_preinit(entity, argc, argv);
 885 
 886     if (level > LOG_TRACE) {
 887         level = LOG_TRACE;
 888     }
 889     if(level > crm_log_level) {
 890         crm_log_level = level;
 891     }
 892 
 893     /* Should we log to syslog */
 894     if (facility == NULL) {
 895         if (pcmk__is_daemon) {
 896             facility = "daemon";
 897         } else {
 898             facility = PCMK__VALUE_NONE;
 899         }
 900         pcmk__set_env_option(PCMK__ENV_LOGFACILITY, facility);
 901     }
 902 
 903     if (pcmk__str_eq(facility, PCMK__VALUE_NONE, pcmk__str_casei)) {
 904         quiet = TRUE;
 905 
 906 
 907     } else {
 908         qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_FACILITY, qb_log_facility2int(facility));
 909     }
 910 
 911     if (pcmk__env_option_enabled(crm_system_name, PCMK__ENV_DEBUG)) {
 912         /* Override the default setting */
 913         crm_log_level = LOG_DEBUG;
 914     }
 915 
 916     /* What lower threshold do we have for sending to syslog */
 917     syslog_priority = pcmk__env_option(PCMK__ENV_LOGPRIORITY);
 918     if (syslog_priority) {
 919         crm_log_priority = crm_priority2int(syslog_priority);
 920     }
 921     qb_log_filter_ctl(QB_LOG_SYSLOG, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FILE, "*",
 922                       crm_log_priority);
 923 
 924     // Log to syslog unless requested to be quiet
 925     if (!quiet) {
 926         qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_TRUE);
 927     }
 928 
 929     /* Should we log to stderr */ 
 930     if (pcmk__env_option_enabled(crm_system_name, PCMK__ENV_STDERR)) {
 931         /* Override the default setting */
 932         to_stderr = TRUE;
 933     }
 934     crm_enable_stderr(to_stderr);
 935 
 936     // Log to a file if we're a daemon or user asked for one
 937     {
 938         const char *logfile = pcmk__env_option(PCMK__ENV_LOGFILE);
 939 
 940         if (!pcmk__str_eq(PCMK__VALUE_NONE, logfile, pcmk__str_casei)
 941             && (pcmk__is_daemon || (logfile != NULL))) {
 942             // Daemons always get a log file, unless explicitly set to "none"
 943             pcmk__add_logfile(logfile);
 944         }
 945     }
 946 
 947     if (pcmk__is_daemon
 948         && pcmk__env_option_enabled(crm_system_name, PCMK__ENV_BLACKBOX)) {
 949         crm_enable_blackbox(0);
 950     }
 951 
 952     /* Summary */
 953     crm_trace("Quiet: %d, facility %s", quiet, f_copy);
 954     pcmk__env_option(PCMK__ENV_LOGFILE);
 955     pcmk__env_option(PCMK__ENV_LOGFACILITY);
 956 
 957     crm_update_callsites();
 958 
 959     /* Ok, now we can start logging... */
 960 
 961     // Disable daemon request if user isn't root or Pacemaker daemon user
 962     if (pcmk__is_daemon) {
 963         const char *user = getenv("USER");
 964 
 965         if (user != NULL && !pcmk__strcase_any_of(user, "root", CRM_DAEMON_USER, NULL)) {
 966             crm_trace("Not switching to corefile directory for %s", user);
 967             pcmk__is_daemon = false;
 968         }
 969     }
 970 
 971     if (pcmk__is_daemon) {
 972         int user = getuid();
 973         struct passwd *pwent = getpwuid(user);
 974 
 975         if (pwent == NULL) {
 976             crm_perror(LOG_ERR, "Cannot get name for uid: %d", user);
 977 
 978         } else if (!pcmk__strcase_any_of(pwent->pw_name, "root", CRM_DAEMON_USER, NULL)) {
 979             crm_trace("Don't change active directory for regular user: %s", pwent->pw_name);
 980 
 981         } else if (chdir(CRM_CORE_DIR) < 0) {
 982             crm_perror(LOG_INFO, "Cannot change active directory to " CRM_CORE_DIR);
 983 
 984         } else {
 985             crm_info("Changed active directory to " CRM_CORE_DIR);
 986         }
 987 
 988         /* Original meanings from signal(7)
 989          *
 990          * Signal       Value     Action   Comment
 991          * SIGTRAP        5        Core    Trace/breakpoint trap
 992          * SIGUSR1     30,10,16    Term    User-defined signal 1
 993          * SIGUSR2     31,12,17    Term    User-defined signal 2
 994          *
 995          * Our usage is as similar as possible
 996          */
 997         mainloop_add_signal(SIGUSR1, crm_enable_blackbox);
 998         mainloop_add_signal(SIGUSR2, crm_disable_blackbox);
 999         mainloop_add_signal(SIGTRAP, crm_trigger_blackbox);
1000 
1001     } else if (!quiet) {
1002         crm_log_args(argc, argv);
1003     }
1004 
1005     return TRUE;
1006 }
1007 
1008 /* returns the old value */
1009 unsigned int
1010 set_crm_log_level(unsigned int level)
     /*  */
1011 {
1012     unsigned int old = crm_log_level;
1013 
1014     if (level > LOG_TRACE) {
1015         level = LOG_TRACE;
1016     }
1017     crm_log_level = level;
1018     crm_update_callsites();
1019     crm_trace("New log level: %d", level);
1020     return old;
1021 }
1022 
1023 void
1024 crm_enable_stderr(int enable)
     /*  */
1025 {
1026     if (enable && qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) {
1027         qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_ENABLED, QB_TRUE);
1028         crm_update_callsites();
1029 
1030     } else if (enable == FALSE) {
1031         qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_ENABLED, QB_FALSE);
1032     }
1033 }
1034 
1035 /*!
1036  * \brief Make logging more verbose
1037  *
1038  * If logging to stderr is not already enabled when this function is called,
1039  * enable it. Otherwise, increase the log level by 1.
1040  *
1041  * \param[in] argc  Ignored
1042  * \param[in] argv  Ignored
1043  */
1044 void
1045 crm_bump_log_level(int argc, char **argv)
     /*  */
1046 {
1047     if (qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_STATE_GET, 0)
1048         != QB_LOG_STATE_ENABLED) {
1049         crm_enable_stderr(TRUE);
1050     } else {
1051         set_crm_log_level(crm_log_level + 1);
1052     }
1053 }
1054 
1055 unsigned int
1056 get_crm_log_level(void)
     /*  */
1057 {
1058     return crm_log_level;
1059 }
1060 
1061 /*!
1062  * \brief Log the command line (once)
1063  *
1064  * \param[in]  Number of values in \p argv
1065  * \param[in]  Command-line arguments (including command name)
1066  *
1067  * \note This function will only log once, even if called with different
1068  *       arguments.
1069  */
1070 void
1071 crm_log_args(int argc, char **argv)
     /*  */
1072 {
1073     static bool logged = false;
1074     gchar *arg_string = NULL;
1075 
1076     if ((argc == 0) || (argv == NULL) || logged) {
1077         return;
1078     }
1079     logged = true;
1080     arg_string = g_strjoinv(" ", argv);
1081     crm_notice("Invoked: %s", arg_string);
1082     g_free(arg_string);
1083 }
1084 
1085 void
1086 crm_log_output_fn(const char *file, const char *function, int line, int level, const char *prefix,
     /*  */
1087                   const char *output)
1088 {
1089     const char *next = NULL;
1090     const char *offset = NULL;
1091 
1092     if (level == LOG_NEVER) {
1093         return;
1094     }
1095 
1096     if (output == NULL) {
1097         if (level != LOG_STDOUT) {
1098             level = LOG_TRACE;
1099         }
1100         output = "-- empty --";
1101     }
1102 
1103     next = output;
1104     do {
1105         offset = next;
1106         next = strchrnul(offset, '\n');
1107         do_crm_log_alias(level, file, function, line, "%s [ %.*s ]", prefix,
1108                          (int)(next - offset), offset);
1109         if (next[0] != 0) {
1110             next++;
1111         }
1112 
1113     } while (next != NULL && next[0] != 0);
1114 }
1115 
1116 void
1117 pcmk__cli_init_logging(const char *name, unsigned int verbosity)
     /*  */
1118 {
1119     crm_log_init(name, LOG_ERR, FALSE, FALSE, 0, NULL, TRUE);
1120 
1121     for (int i = 0; i < verbosity; i++) {
1122         /* These arguments are ignored, so pass placeholders. */
1123         crm_bump_log_level(0, NULL);
1124     }
1125 }
1126 
1127 /*!
1128  * \brief Log XML line-by-line in a formatted fashion
1129  *
1130  * \param[in] level  Priority at which to log the messages
1131  * \param[in] text   Prefix for each line
1132  * \param[in] xml    XML to log
1133  *
1134  * \note This does nothing when \p level is \p LOG_STDOUT.
1135  * \note Do not call this function directly. It should be called only from the
1136  *       \p do_crm_log_xml() macro.
1137  */
1138 void
1139 pcmk_log_xml_impl(uint8_t level, const char *text, const xmlNode *xml)
     /*  */
1140 {
1141     if (xml == NULL) {
1142         do_crm_log(level, "%s%sNo data to dump as XML",
1143                    pcmk__s(text, ""), pcmk__str_empty(text)? "" : " ");
1144 
1145     } else {
1146         if (logger_out == NULL) {
1147             CRM_CHECK(pcmk__log_output_new(&logger_out) == pcmk_rc_ok, return);
1148         }
1149 
1150         pcmk__output_set_log_level(logger_out, level);
1151         pcmk__xml_show(logger_out, text, xml, 1,
1152                        pcmk__xml_fmt_pretty
1153                        |pcmk__xml_fmt_open
1154                        |pcmk__xml_fmt_children
1155                        |pcmk__xml_fmt_close);
1156     }
1157 }
1158 
1159 /*!
1160  * \internal
1161  * \brief Free the logging library's internal log output object
1162  */
1163 void
1164 pcmk__free_common_logger(void)
     /*  */
1165 {
1166     if (logger_out != NULL) {
1167         logger_out->finish(logger_out, CRM_EX_OK, true, NULL);
1168         pcmk__output_free(logger_out);
1169         logger_out = NULL;
1170     }
1171 }
1172 
1173 // Deprecated functions kept only for backward API compatibility
1174 // LCOV_EXCL_START
1175 
1176 #include <crm/common/logging_compat.h>
1177 
1178 gboolean
1179 crm_log_cli_init(const char *entity)
     /*  */
1180 {
1181     pcmk__cli_init_logging(entity, 0);
1182     return TRUE;
1183 }
1184 
1185 gboolean
1186 crm_add_logfile(const char *filename)
     /*  */
1187 {
1188     return pcmk__add_logfile(filename) == pcmk_rc_ok;
1189 }
1190 
1191 // LCOV_EXCL_STOP
1192 // End deprecated API
/* */
root/lib/common/logging.c

DEFINITIONS
