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

DEFINITIONS
