diff --git a/include/crm/common/logging_internal.h b/include/crm/common/logging_internal.h index c6c63c4e7a..0b24e07bb1 100644 --- a/include/crm/common/logging_internal.h +++ b/include/crm/common/logging_internal.h @@ -1,302 +1,322 @@ /* * Copyright 2015-2025 the Pacemaker project contributors * * The version control history for this file may have further details. * * This source code is licensed under the GNU General Public License version 2 * or later (GPLv2+) WITHOUT ANY WARRANTY. */ #ifndef PCMK__CRM_COMMON_LOGGING_INTERNAL__H #define PCMK__CRM_COMMON_LOGGING_INTERNAL__H #include #include // pcmk__is_set() #include #include #ifdef __cplusplus extern "C" { #endif +/* Define custom log priorities. + * + * syslog(3) uses int for priorities, but libqb's struct qb_log_callsite uses + * uint8_t, so make sure they fit in the latter. + */ + +#ifndef PCMK__LOG_STDOUT +/*! + * \internal + * \brief Request to print message to \c stdout instead of logging it + * + * Some callees print nothing when this is the log level. + * + * \note This value must stay the same as \c LOG_STDOUT until the latter is + * dropped. Be mindful of public API functions that may pass arbitrary + * integer log levels as well. + */ +#define PCMK__LOG_STDOUT 254 +#endif // PCMK__LOG_STDOUT + /*! * \internal * \brief Log a message at \c LOG_EMERG level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__emerg(fmt, args...) qb_log(LOG_EMERG, fmt, ##args) /*! * \internal * \brief Log a message at \c LOG_CRIT level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__crit(fmt, args...) qb_log(LOG_CRIT, fmt, ##args) /*! * \internal * \brief Log a message at \c LOG_ERR level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__err(fmt, args...) qb_log(LOG_ERR, fmt, ##args) /*! * \internal * \brief Log a message at \c LOG_WARN level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__warn(fmt, args...) qb_log(LOG_WARNING, fmt, ##args) /*! * \internal * \brief Log a message at \c LOG_NOTICE level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__notice(fmt, args...) qb_log(LOG_NOTICE, fmt, ##args) /*! * \internal * \brief Log a message at \c LOG_INFO level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__info(fmt, args...) qb_log(LOG_INFO, fmt, ##args) /*! * \internal * \brief Log a message at \c LOG_DEBUG level * * \param[in] fmt \c printf() format string for log message * \param[in] args Format string arguments */ #define pcmk__debug(fmt, args...) do_crm_log_unlikely(LOG_DEBUG, fmt, ##args) /* Some warnings are too noisy when logged every time a given function is called * (for example, using a deprecated feature). As an alternative, we allow * warnings to be logged once per invocation of the calling program. Each of * those warnings needs a flag defined here. */ enum pcmk__warnings { pcmk__wo_blind = (1 << 0), pcmk__wo_record_pending = (1 << 1), pcmk__wo_require_all = (1 << 4), pcmk__wo_order_score = (1 << 5), pcmk__wo_group_order = (1 << 11), pcmk__wo_group_coloc = (1 << 12), pcmk__wo_set_ordering = (1 << 15), pcmk__wo_rdisc_enabled = (1 << 16), pcmk__wo_op_attr_expr = (1 << 19), pcmk__wo_clone_master_max = (1 << 23), pcmk__wo_clone_master_node_max = (1 << 24), pcmk__wo_master_role = (1 << 26), pcmk__wo_slave_role = (1 << 27), }; /*! * \internal * \brief Log a warning once per invocation of calling program * * \param[in] wo_flag enum pcmk__warnings value for this warning * \param[in] fmt... printf(3)-style format and arguments */ #define pcmk__warn_once(wo_flag, fmt...) do { \ if (!pcmk__is_set(pcmk__warnings, wo_flag)) { \ if (wo_flag == pcmk__wo_blind) { \ pcmk__warn(fmt); \ } else { \ pcmk__config_warn(fmt); \ } \ pcmk__warnings = pcmk__set_flags_as(__func__, __LINE__, \ LOG_TRACE, \ "Warn-once", "logging", \ pcmk__warnings, \ (wo_flag), #wo_flag); \ } \ } while (0) typedef void (*pcmk__config_error_func) (void *ctx, const char *msg, ...) G_GNUC_PRINTF(2, 3); typedef void (*pcmk__config_warning_func) (void *ctx, const char *msg, ...) G_GNUC_PRINTF(2, 3); extern pcmk__config_error_func pcmk__config_error_handler; extern pcmk__config_warning_func pcmk__config_warning_handler; extern void *pcmk__config_error_context; extern void *pcmk__config_warning_context; void pcmk__set_config_error_handler(pcmk__config_error_func error_handler, void *error_context); void pcmk__set_config_warning_handler(pcmk__config_warning_func warning_handler, void *warning_context); /* Pacemaker library functions set this when a configuration error is found, * which turns on extra messages at the end of processing. */ extern bool pcmk__config_has_error; /* Pacemaker library functions set this when a configuration warning is found, * which turns on extra messages at the end of processing. */ extern bool pcmk__config_has_warning; /*! * \internal * \brief Log an error and make crm_verify return failure status * * \param[in] fmt... printf(3)-style format string and arguments */ #define pcmk__config_err(fmt...) do { \ pcmk__config_has_error = true; \ if (pcmk__config_error_handler == NULL) { \ pcmk__err(fmt); \ } else { \ pcmk__config_error_handler(pcmk__config_error_context, fmt); \ } \ } while (0) /*! * \internal * \brief Log a warning and make crm_verify return failure status * * \param[in] fmt... printf(3)-style format string and arguments */ #define pcmk__config_warn(fmt...) do { \ pcmk__config_has_warning = true; \ if (pcmk__config_warning_handler == NULL) { \ pcmk__warn(fmt); \ } else { \ pcmk__config_warning_handler(pcmk__config_warning_context, fmt);\ } \ } while (0) /*! * \internal * \brief Execute code depending on whether trace logging is enabled * * This is similar to \p do_crm_log_unlikely() except instead of logging, it * selects one of two code blocks to execute. * * \param[in] if_action Code block to execute if trace logging is enabled * \param[in] else_action Code block to execute if trace logging is not enabled * * \note Neither \p if_action nor \p else_action can contain a \p break or * \p continue statement. */ #define pcmk__if_tracing(if_action, else_action) do { \ static struct qb_log_callsite *trace_cs = NULL; \ \ if (trace_cs == NULL) { \ trace_cs = qb_log_callsite_get(__func__, __FILE__, \ "if_tracing", LOG_TRACE, \ __LINE__, crm_trace_nonlog); \ } \ if (crm_is_callsite_active(trace_cs, LOG_TRACE, \ crm_trace_nonlog)) { \ if_action; \ } else { \ else_action; \ } \ } while (0) /*! * \internal * \brief Log XML changes line-by-line in a formatted fashion * * \param[in] level Priority at which to log the messages * \param[in] xml XML to log * - * \note This does nothing when \p level is \c LOG_STDOUT. + * \note This does nothing when \p level is \c PCMK__LOG_STDOUT. */ #define pcmk__log_xml_changes(level, xml) do { \ uint8_t _level = pcmk__clip_log_level(level); \ static struct qb_log_callsite *xml_cs = NULL; \ \ switch (_level) { \ - case LOG_STDOUT: \ + case PCMK__LOG_STDOUT: \ case LOG_NEVER: \ break; \ default: \ if (xml_cs == NULL) { \ xml_cs = qb_log_callsite_get(__func__, __FILE__, \ "xml-changes", _level, \ __LINE__, 0); \ } \ if (crm_is_callsite_active(xml_cs, _level, 0)) { \ pcmk__log_xml_changes_as(__FILE__, __func__, __LINE__, \ 0, _level, xml); \ } \ break; \ } \ } while(0) /*! * \internal * \brief Log an XML patchset line-by-line in a formatted fashion * * \param[in] level Priority at which to log the messages * \param[in] patchset XML patchset to log * - * \note This does nothing when \p level is \c LOG_STDOUT. + * \note This does nothing when \p level is \c PCMK__LOG_STDOUT. */ #define pcmk__log_xml_patchset(level, patchset) do { \ uint8_t _level = pcmk__clip_log_level(level); \ static struct qb_log_callsite *xml_cs = NULL; \ \ switch (_level) { \ - case LOG_STDOUT: \ + case PCMK__LOG_STDOUT: \ case LOG_NEVER: \ break; \ default: \ if (xml_cs == NULL) { \ xml_cs = qb_log_callsite_get(__func__, __FILE__, \ "xml-patchset", _level, \ __LINE__, 0); \ } \ if (crm_is_callsite_active(xml_cs, _level, 0)) { \ pcmk__log_xml_patchset_as(__FILE__, __func__, __LINE__, \ 0, _level, patchset); \ } \ break; \ } \ } while(0) void pcmk__log_xml_changes_as(const char *file, const char *function, uint32_t line, uint32_t tags, uint8_t level, const xmlNode *xml); void pcmk__log_xml_patchset_as(const char *file, const char *function, uint32_t line, uint32_t tags, uint8_t level, const xmlNode *patchset); /*! * \internal * \brief Initialize logging for command line tools * * \param[in] name The name of the program * \param[in] verbosity How verbose to be in logging * * \note \p verbosity is not the same as the logging level (LOG_ERR, etc.). */ void pcmk__cli_init_logging(const char *name, unsigned int verbosity); int pcmk__add_logfile(const char *filename); void pcmk__add_logfiles(gchar **log_files, pcmk__output_t *out); void pcmk__free_common_logger(void); #ifdef __cplusplus } #endif #endif // PCMK__CRM_COMMON_LOGGING_INTERNAL__H diff --git a/lib/common/iso8601.c b/lib/common/iso8601.c index 088d64a2ec..5705d6694d 100644 --- a/lib/common/iso8601.c +++ b/lib/common/iso8601.c @@ -1,2260 +1,2260 @@ /* * Copyright 2005-2025 the Pacemaker project contributors * * The version control history for this file may have further details. * * This source code is licensed under the GNU Lesser General Public License * version 2.1 or later (LGPLv2.1+) WITHOUT ANY WARRANTY. */ /* * References: * https://en.wikipedia.org/wiki/ISO_8601 * http://www.staff.science.uu.nl/~gent0113/calendar/isocalendar.htm */ #include #include #include #include #include #include // INT_MIN, INT_MAX #include #include #include #include #include "crmcommon_private.h" /* * Andrew's code was originally written for OSes whose "struct tm" contains: * long tm_gmtoff; :: Seconds east of UTC * const char *tm_zone; :: Timezone abbreviation * Some OSes lack these, instead having: * time_t (or long) timezone; :: "difference between UTC and local standard time" * char *tzname[2] = { "...", "..." }; * I (David Lee) confess to not understanding the details. So my attempted * generalisations for where their use is necessary may be flawed. * * 1. Does "difference between ..." subtract the same or opposite way? * 2. Should it use "altzone" instead of "timezone"? * 3. Should it use tzname[0] or tzname[1]? Interaction with timezone/altzone? */ #if defined(HAVE_STRUCT_TM_TM_GMTOFF) # define GMTOFF(tm) ((tm)->tm_gmtoff) #else /* Note: extern variable; macro argument not actually used. */ # define GMTOFF(tm) (-timezone+daylight) #endif #define HOUR_SECONDS (60 * 60) #define DAY_SECONDS (HOUR_SECONDS * 24) /*! * \internal * \brief Validate a seconds/microseconds tuple * * The microseconds value must be in the correct range, and if both are nonzero * they must have the same sign. * * \param[in] sec Seconds * \param[in] usec Microseconds * * \return true if the seconds/microseconds tuple is valid, or false otherwise */ #define valid_sec_usec(sec, usec) \ ((QB_ABS(usec) < QB_TIME_US_IN_SEC) \ && (((sec) == 0) || ((usec) == 0) || (((sec) < 0) == ((usec) < 0)))) // A date/time or duration struct crm_time_s { int years; // Calendar year (date/time) or number of years (duration) int months; // Number of months (duration only) int days; // Ordinal day of year (date/time) or number of days (duration) int seconds; // Seconds of day (date/time) or number of seconds (duration) int offset; // Seconds offset from UTC (date/time only) bool duration; // True if duration }; static crm_time_t *parse_date(const char *date_str); static crm_time_t * crm_get_utc_time(const crm_time_t *dt) { crm_time_t *utc = NULL; if (dt == NULL) { errno = EINVAL; return NULL; } utc = crm_time_new_undefined(); utc->years = dt->years; utc->days = dt->days; utc->seconds = dt->seconds; utc->offset = 0; if (dt->offset) { crm_time_add_seconds(utc, -dt->offset); } else { /* Durations (which are the only things that can include months, never have a timezone */ utc->months = dt->months; } crm_time_log(LOG_TRACE, "utc-source", dt, crm_time_log_date | crm_time_log_timeofday | crm_time_log_with_timezone); crm_time_log(LOG_TRACE, "utc-target", utc, crm_time_log_date | crm_time_log_timeofday | crm_time_log_with_timezone); return utc; } crm_time_t * crm_time_new(const char *date_time) { tzset(); if (date_time == NULL) { return pcmk__copy_timet(time(NULL)); } return parse_date(date_time); } /*! * \brief Allocate memory for an uninitialized time object * * \return Newly allocated time object * \note The caller is responsible for freeing the return value using * crm_time_free(). */ crm_time_t * crm_time_new_undefined(void) { return (crm_time_t *) pcmk__assert_alloc(1, sizeof(crm_time_t)); } /*! * \brief Check whether a time object has been initialized yet * * \param[in] t Time object to check * * \return TRUE if time object has been initialized, FALSE otherwise */ bool crm_time_is_defined(const crm_time_t *t) { // Any nonzero member indicates something has been done to t return (t != NULL) && (t->years || t->months || t->days || t->seconds || t->offset || t->duration); } void crm_time_free(crm_time_t * dt) { if (dt == NULL) { return; } free(dt); } static int year_days(int year) { int d = 365; if (crm_time_leapyear(year)) { d++; } return d; } /* From http://myweb.ecu.edu/mccartyr/ISOwdALG.txt : * * 5. Find the Jan1Weekday for Y (Monday=1, Sunday=7) * YY = (Y-1) % 100 * C = (Y-1) - YY * G = YY + YY/4 * Jan1Weekday = 1 + (((((C / 100) % 4) x 5) + G) % 7) */ int crm_time_january1_weekday(int year) { int YY = (year - 1) % 100; int C = (year - 1) - YY; int G = YY + YY / 4; int jan1 = 1 + (((((C / 100) % 4) * 5) + G) % 7); crm_trace("YY=%d, C=%d, G=%d", YY, C, G); crm_trace("January 1 %.4d: %d", year, jan1); return jan1; } int crm_time_weeks_in_year(int year) { int weeks = 52; int jan1 = crm_time_january1_weekday(year); /* if jan1 == thursday */ if (jan1 == 4) { weeks++; } else { jan1 = crm_time_january1_weekday(year + 1); /* if dec31 == thursday aka. jan1 of next year is a friday */ if (jan1 == 5) { weeks++; } } return weeks; } // Jan-Dec plus Feb of leap years static int month_days[13] = { 31, 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31, 29 }; /*! * \brief Return number of days in given month of given year * * \param[in] month Ordinal month (1-12) * \param[in] year Gregorian year * * \return Number of days in given month (0 if given month or year is invalid) */ int crm_time_days_in_month(int month, int year) { if ((month < 1) || (month > 12) || (year < 1)) { return 0; } if ((month == 2) && crm_time_leapyear(year)) { month = 13; } return month_days[month - 1]; } bool crm_time_leapyear(int year) { gboolean is_leap = FALSE; if (year % 4 == 0) { is_leap = TRUE; } if (year % 100 == 0 && year % 400 != 0) { is_leap = FALSE; } return is_leap; } /*! * \internal * \brief Get ordinal day number of year corresponding to given date * * \param[in] y Year * \param[in] m Month (1-12) * \param[in] d Day of month (1-31) * * \return Day number of year \p y corresponding to month \p m and day \p d, * or 0 for invalid arguments */ static int get_ordinal_days(uint32_t y, uint32_t m, uint32_t d) { int result = 0; CRM_CHECK((y > 0) && (y <= INT_MAX) && (m >= 1) && (m <= 12) && (d >= 1) && (d <= 31), return 0); result = d; for (int lpc = 1; lpc < m; lpc++) { result += crm_time_days_in_month(lpc, y); } return result; } void crm_time_log_alias(int log_level, const char *file, const char *function, int line, const char *prefix, const crm_time_t *date_time, int flags) { char *date_s = crm_time_as_string(date_time, flags); - if (log_level == LOG_STDOUT) { + if (log_level == PCMK__LOG_STDOUT) { printf("%s%s%s\n", (prefix? prefix : ""), (prefix? ": " : ""), date_s); } else { do_crm_log_alias(log_level, file, function, line, "%s%s%s", (prefix? prefix : ""), (prefix? ": " : ""), date_s); } free(date_s); } static void crm_time_get_sec(int sec, uint32_t *h, uint32_t *m, uint32_t *s) { uint32_t hours, minutes, seconds; seconds = QB_ABS(sec); hours = seconds / HOUR_SECONDS; seconds -= HOUR_SECONDS * hours; minutes = seconds / 60; seconds -= 60 * minutes; crm_trace("%d == %.2" PRIu32 ":%.2" PRIu32 ":%.2" PRIu32, sec, hours, minutes, seconds); *h = hours; *m = minutes; *s = seconds; } int crm_time_get_timeofday(const crm_time_t *dt, uint32_t *h, uint32_t *m, uint32_t *s) { crm_time_get_sec(dt->seconds, h, m, s); return TRUE; } int crm_time_get_timezone(const crm_time_t *dt, uint32_t *h, uint32_t *m) { uint32_t s; crm_time_get_sec(dt->seconds, h, m, &s); return TRUE; } long long crm_time_get_seconds(const crm_time_t *dt) { int lpc; crm_time_t *utc = NULL; long long in_seconds = 0; if (dt == NULL) { return 0; } // @TODO This is inefficient if dt is already in UTC utc = crm_get_utc_time(dt); if (utc == NULL) { return 0; } // @TODO We should probably use <= if dt is a duration for (lpc = 1; lpc < utc->years; lpc++) { long long dmax = year_days(lpc); in_seconds += DAY_SECONDS * dmax; } /* utc->months can be set only for durations. By definition, the value * varies depending on the (unknown) start date to which the duration will * be applied. Assume 30-day months so that something vaguely sane happens * in this case. */ if (utc->months > 0) { in_seconds += DAY_SECONDS * 30 * (long long) (utc->months); } if (utc->days > 0) { in_seconds += DAY_SECONDS * (long long) (utc->days - 1); } in_seconds += utc->seconds; crm_time_free(utc); return in_seconds; } #define EPOCH_SECONDS 62135596800ULL /* Calculated using crm_time_get_seconds() */ long long crm_time_get_seconds_since_epoch(const crm_time_t *dt) { return (dt == NULL)? 0 : (crm_time_get_seconds(dt) - EPOCH_SECONDS); } int crm_time_get_gregorian(const crm_time_t *dt, uint32_t *y, uint32_t *m, uint32_t *d) { int months = 0; int days = dt->days; if(dt->years != 0) { for (months = 1; months <= 12 && days > 0; months++) { int mdays = crm_time_days_in_month(months, dt->years); if (mdays >= days) { break; } else { days -= mdays; } } } else if (dt->months) { /* This is a duration including months, don't convert the days field */ months = dt->months; } else { /* This is a duration not including months, still don't convert the days field */ } *y = dt->years; *m = months; *d = days; crm_trace("%.4d-%.3d -> %.4d-%.2d-%.2d", dt->years, dt->days, dt->years, months, days); return TRUE; } int crm_time_get_ordinal(const crm_time_t *dt, uint32_t *y, uint32_t *d) { *y = dt->years; *d = dt->days; return TRUE; } int crm_time_get_isoweek(const crm_time_t *dt, uint32_t *y, uint32_t *w, uint32_t *d) { /* * Monday 29 December 2008 is written "2009-W01-1" * Sunday 3 January 2010 is written "2009-W53-7" */ int year_num = 0; int jan1 = crm_time_january1_weekday(dt->years); int h = -1; CRM_CHECK(dt->days > 0, return FALSE); /* 6. Find the Weekday for Y M D */ h = dt->days + jan1 - 1; *d = 1 + ((h - 1) % 7); /* 7. Find if Y M D falls in YearNumber Y-1, WeekNumber 52 or 53 */ if (dt->days <= (8 - jan1) && jan1 > 4) { crm_trace("year--, jan1=%d", jan1); year_num = dt->years - 1; *w = crm_time_weeks_in_year(year_num); } else { year_num = dt->years; } /* 8. Find if Y M D falls in YearNumber Y+1, WeekNumber 1 */ if (year_num == dt->years) { int dmax = year_days(year_num); int correction = 4 - *d; if ((dmax - dt->days) < correction) { crm_trace("year++, jan1=%d, i=%d vs. %d", jan1, dmax - dt->days, correction); year_num = dt->years + 1; *w = 1; } } /* 9. Find if Y M D falls in YearNumber Y, WeekNumber 1 through 53 */ if (year_num == dt->years) { int j = dt->days + (7 - *d) + (jan1 - 1); *w = j / 7; if (jan1 > 4) { *w -= 1; } } *y = year_num; crm_trace("Converted %.4d-%.3d to %.4" PRIu32 "-W%.2" PRIu32 "-%" PRIu32, dt->years, dt->days, *y, *w, *d); return TRUE; } #define DATE_MAX 128 /*! * \internal * \brief Print "." to a buffer * * \param[in] sec Seconds * \param[in] usec Microseconds (must be of same sign as \p sec and of * absolute value less than \p QB_TIME_US_IN_SEC) * \param[in,out] buf Result buffer * \param[in,out] offset Current offset within \p buf */ static inline void sec_usec_as_string(long long sec, int usec, char *buf, size_t *offset) { *offset += snprintf(buf + *offset, DATE_MAX - *offset, "%s%lld.%06d", ((sec == 0) && (usec < 0))? "-" : "", sec, QB_ABS(usec)); } /*! * \internal * \brief Get a string representation of a duration * * \param[in] dt Time object to interpret as a duration * \param[in] usec Microseconds to add to \p dt * \param[in] show_usec Whether to include microseconds in \p result * \param[out] result Where to store the result string */ static void crm_duration_as_string(const crm_time_t *dt, int usec, bool show_usec, char *result) { size_t offset = 0; pcmk__assert(valid_sec_usec(dt->seconds, usec)); if (dt->years) { offset += snprintf(result + offset, DATE_MAX - offset, "%4d year%s ", dt->years, pcmk__plural_s(dt->years)); } if (dt->months) { offset += snprintf(result + offset, DATE_MAX - offset, "%2d month%s ", dt->months, pcmk__plural_s(dt->months)); } if (dt->days) { offset += snprintf(result + offset, DATE_MAX - offset, "%2d day%s ", dt->days, pcmk__plural_s(dt->days)); } // At least print seconds (and optionally usecs) if ((offset == 0) || (dt->seconds != 0) || (show_usec && (usec != 0))) { if (show_usec) { sec_usec_as_string(dt->seconds, usec, result, &offset); } else { offset += snprintf(result + offset, DATE_MAX - offset, "%d", dt->seconds); } offset += snprintf(result + offset, DATE_MAX - offset, " second%s", pcmk__plural_s(dt->seconds)); } // More than one minute, so provide a more readable breakdown into units if (QB_ABS(dt->seconds) >= 60) { uint32_t h = 0; uint32_t m = 0; uint32_t s = 0; uint32_t u = QB_ABS(usec); bool print_sec_component = false; crm_time_get_sec(dt->seconds, &h, &m, &s); print_sec_component = ((s != 0) || (show_usec && (u != 0))); offset += snprintf(result + offset, DATE_MAX - offset, " ("); if (h) { offset += snprintf(result + offset, DATE_MAX - offset, "%" PRIu32 " hour%s%s", h, pcmk__plural_s(h), ((m != 0) || print_sec_component)? " " : ""); } if (m) { offset += snprintf(result + offset, DATE_MAX - offset, "%" PRIu32 " minute%s%s", m, pcmk__plural_s(m), print_sec_component? " " : ""); } if (print_sec_component) { if (show_usec) { sec_usec_as_string(s, u, result, &offset); } else { offset += snprintf(result + offset, DATE_MAX - offset, "%" PRIu32, s); } offset += snprintf(result + offset, DATE_MAX - offset, " second%s", pcmk__plural_s(dt->seconds)); } offset += snprintf(result + offset, DATE_MAX - offset, ")"); } } /*! * \internal * \brief Get a string representation of a time object * * \param[in] dt Time to convert to string * \param[in] usec Microseconds to add to \p dt * \param[in] flags Group of \p crm_time_* string format options * \param[out] result Where to store the result string * * \note \p result must be of size \p DATE_MAX or larger. */ static void time_as_string_common(const crm_time_t *dt, int usec, uint32_t flags, char *result) { crm_time_t *utc = NULL; size_t offset = 0; if (!crm_time_is_defined(dt)) { strcpy(result, ""); return; } pcmk__assert(valid_sec_usec(dt->seconds, usec)); /* Simple cases: as duration, seconds, or seconds since epoch. * These never depend on time zone. */ if (pcmk__is_set(flags, crm_time_log_duration)) { crm_duration_as_string(dt, usec, pcmk__is_set(flags, crm_time_usecs), result); return; } if (pcmk__any_flags_set(flags, crm_time_seconds|crm_time_epoch)) { long long seconds = 0; if (pcmk__is_set(flags, crm_time_seconds)) { seconds = crm_time_get_seconds(dt); } else { seconds = crm_time_get_seconds_since_epoch(dt); } if (pcmk__is_set(flags, crm_time_usecs)) { sec_usec_as_string(seconds, usec, result, &offset); } else { snprintf(result, DATE_MAX, "%lld", seconds); } return; } // Convert to UTC if local timezone was not requested if ((dt->offset != 0) && !pcmk__is_set(flags, crm_time_log_with_timezone)) { crm_trace("UTC conversion"); utc = crm_get_utc_time(dt); dt = utc; } // As readable string if (pcmk__is_set(flags, crm_time_log_date)) { if (pcmk__is_set(flags, crm_time_weeks)) { // YYYY-WW-D uint32_t y = 0; uint32_t w = 0; uint32_t d = 0; if (crm_time_get_isoweek(dt, &y, &w, &d)) { offset += snprintf(result + offset, DATE_MAX - offset, "%" PRIu32 "-W%.2" PRIu32 "-%" PRIu32, y, w, d); } } else if (pcmk__is_set(flags, crm_time_ordinal)) { // YYYY-DDD uint32_t y = 0; uint32_t d = 0; if (crm_time_get_ordinal(dt, &y, &d)) { offset += snprintf(result + offset, DATE_MAX - offset, "%" PRIu32 "-%.3" PRIu32, y, d); } } else { // YYYY-MM-DD uint32_t y = 0; uint32_t m = 0; uint32_t d = 0; if (crm_time_get_gregorian(dt, &y, &m, &d)) { offset += snprintf(result + offset, DATE_MAX - offset, "%.4" PRIu32 "-%.2" PRIu32 "-%.2" PRIu32, y, m, d); } } } if (pcmk__is_set(flags, crm_time_log_timeofday)) { uint32_t h = 0, m = 0, s = 0; if (offset > 0) { offset += snprintf(result + offset, DATE_MAX - offset, " "); } if (crm_time_get_timeofday(dt, &h, &m, &s)) { offset += snprintf(result + offset, DATE_MAX - offset, "%.2" PRIu32 ":%.2" PRIu32 ":%.2" PRIu32, h, m, s); if (pcmk__is_set(flags, crm_time_usecs)) { offset += snprintf(result + offset, DATE_MAX - offset, ".%06" PRIu32, QB_ABS(usec)); } } if (pcmk__is_set(flags, crm_time_log_with_timezone) && (dt->offset != 0)) { crm_time_get_sec(dt->offset, &h, &m, &s); offset += snprintf(result + offset, DATE_MAX - offset, " %c%.2" PRIu32 ":%.2" PRIu32, ((dt->offset < 0)? '-' : '+'), h, m); } else { offset += snprintf(result + offset, DATE_MAX - offset, "Z"); } } crm_time_free(utc); } /*! * \brief Get a string representation of a \p crm_time_t object * * \param[in] dt Time to convert to string * \param[in] flags Group of \p crm_time_* string format options * * \note The caller is responsible for freeing the return value using \p free(). */ char * crm_time_as_string(const crm_time_t *dt, int flags) { char result[DATE_MAX] = { '\0', }; time_as_string_common(dt, 0, flags, result); return pcmk__str_copy(result); } /*! * \internal * \brief Determine number of seconds from an hour:minute:second string * * \param[in] time_str Time specification string * \param[out] result Number of seconds equivalent to time_str * * \return TRUE if specification was valid, FALSE (and set errno) otherwise * \note This may return the number of seconds in a day (which is out of bounds * for a time object) if given 24:00:00. */ static bool crm_time_parse_sec(const char *time_str, int *result) { int rc; uint32_t hour = 0; uint32_t minute = 0; uint32_t second = 0; *result = 0; // Must have at least hour, but minutes and seconds are optional rc = sscanf(time_str, "%" SCNu32 ":%" SCNu32 ":%" SCNu32, &hour, &minute, &second); if (rc == 1) { rc = sscanf(time_str, "%2" SCNu32 "%2" SCNu32 "%2" SCNu32, &hour, &minute, &second); } if (rc == 0) { pcmk__err("%s is not a valid ISO 8601 time specification", time_str); errno = EINVAL; return FALSE; } crm_trace("Got valid time: %.2" PRIu32 ":%.2" PRIu32 ":%.2" PRIu32, hour, minute, second); if ((hour == 24) && (minute == 0) && (second == 0)) { // Equivalent to 00:00:00 of next day, return number of seconds in day } else if (hour >= 24) { pcmk__err("%s is not a valid ISO 8601 time specification " "because %" PRIu32 " is not a valid hour", time_str, hour); errno = EINVAL; return FALSE; } if (minute >= 60) { pcmk__err("%s is not a valid ISO 8601 time specification " "because %" PRIu32 " is not a valid minute", time_str, minute); errno = EINVAL; return FALSE; } if (second >= 60) { pcmk__err("%s is not a valid ISO 8601 time specification " "because %" PRIu32 " is not a valid second", time_str, second); errno = EINVAL; return FALSE; } *result = (hour * HOUR_SECONDS) + (minute * 60) + second; return TRUE; } static bool crm_time_parse_offset(const char *offset_str, int *offset) { tzset(); if (offset_str == NULL) { // Use local offset #if defined(HAVE_STRUCT_TM_TM_GMTOFF) time_t now = time(NULL); struct tm *now_tm = localtime(&now); #endif int h_offset = GMTOFF(now_tm) / HOUR_SECONDS; int m_offset = (GMTOFF(now_tm) - (HOUR_SECONDS * h_offset)) / 60; if (h_offset < 0 && m_offset < 0) { m_offset = 0 - m_offset; } *offset = (HOUR_SECONDS * h_offset) + (60 * m_offset); return TRUE; } if (offset_str[0] == 'Z') { // @TODO invalid if anything after? *offset = 0; return TRUE; } *offset = 0; if ((offset_str[0] == '+') || (offset_str[0] == '-') || isdigit((int)offset_str[0])) { gboolean negate = FALSE; if (offset_str[0] == '+') { offset_str++; } else if (offset_str[0] == '-') { negate = TRUE; offset_str++; } if (crm_time_parse_sec(offset_str, offset) == FALSE) { return FALSE; } if (negate) { *offset = 0 - *offset; } } // @TODO else invalid? return TRUE; } /*! * \internal * \brief Parse the time portion of an ISO 8601 date/time string * * \param[in] time_str Time portion of specification (after any 'T') * \param[in,out] a_time Time object to parse into * * \return TRUE if valid time was parsed, FALSE (and set errno) otherwise * \note This may add a day to a_time (if the time is 24:00:00). */ static bool crm_time_parse(const char *time_str, crm_time_t *a_time) { uint32_t h, m, s; char *offset_s = NULL; tzset(); if (time_str) { if (crm_time_parse_sec(time_str, &(a_time->seconds)) == FALSE) { return FALSE; } offset_s = strstr(time_str, "Z"); if (offset_s == NULL) { offset_s = strstr(time_str, " "); if (offset_s) { while (isspace(offset_s[0])) { offset_s++; } } } } if (crm_time_parse_offset(offset_s, &(a_time->offset)) == FALSE) { return FALSE; } crm_time_get_sec(a_time->offset, &h, &m, &s); crm_trace("Got tz: %c%2." PRIu32 ":%.2" PRIu32, (a_time->offset < 0)? '-' : '+', h, m); if (a_time->seconds == DAY_SECONDS) { // 24:00:00 == 00:00:00 of next day a_time->seconds = 0; crm_time_add_days(a_time, 1); } return TRUE; } /* * \internal * \brief Parse a time object from an ISO 8601 date/time specification * * \param[in] date_str ISO 8601 date/time specification (or * \c PCMK__VALUE_EPOCH) * * \return New time object on success, NULL (and set errno) otherwise */ static crm_time_t * parse_date(const char *date_str) { const char *time_s = NULL; crm_time_t *dt = NULL; uint32_t year = 0U; uint32_t month = 0U; uint32_t day = 0U; uint32_t week = 0U; int rc = 0; if (pcmk__str_empty(date_str)) { pcmk__err("No ISO 8601 date/time specification given"); goto invalid; } if ((date_str[0] == 'T') || ((strlen(date_str) > 2) && (date_str[2] == ':'))) { /* Just a time supplied - Infer current date */ dt = crm_time_new(NULL); if (date_str[0] == 'T') { time_s = date_str + 1; } else { time_s = date_str; } goto parse_time; } dt = crm_time_new_undefined(); if ((strncasecmp(PCMK__VALUE_EPOCH, date_str, 5) == 0) && ((date_str[5] == '\0') || (date_str[5] == '/') || isspace(date_str[5]))) { dt->days = 1; dt->years = 1970; crm_time_log(LOG_TRACE, "Unpacked", dt, crm_time_log_date | crm_time_log_timeofday); return dt; } /* YYYY-MM-DD */ rc = sscanf(date_str, "%" SCNu32 "-%" SCNu32 "-%" SCNu32 "", &year, &month, &day); if (rc == 1) { /* YYYYMMDD */ rc = sscanf(date_str, "%4" SCNu32 "%2" SCNu32 "%2" SCNu32 "", &year, &month, &day); } if (rc == 3) { if ((month < 1U) || (month > 12U)) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid month", date_str, month); goto invalid; } else if ((year < 1U) || (year > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid year", date_str, year); goto invalid; } else if ((day < 1) || (day > INT_MAX) || (day > crm_time_days_in_month(month, year))) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid day of the month", date_str, day); goto invalid; } else { dt->years = year; dt->days = get_ordinal_days(year, month, day); crm_trace("Parsed Gregorian date '%.4" PRIu32 "-%.3d' " "from date string '%s'", year, dt->days, date_str); } goto parse_time; } /* YYYY-DDD */ rc = sscanf(date_str, "%" SCNu32 "-%" SCNu32, &year, &day); if (rc == 2) { if ((year < 1U) || (year > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid year", date_str, year); goto invalid; } else if ((day < 1U) || (day > INT_MAX) || (day > year_days(year))) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid day of year %" PRIu32 " (1-%d)", date_str, day, year, year_days(year)); goto invalid; } crm_trace("Parsed ordinal year %d and days %d from date string '%s'", year, day, date_str); dt->days = day; dt->years = year; goto parse_time; } /* YYYY-Www-D */ rc = sscanf(date_str, "%" SCNu32 "-W%" SCNu32 "-%" SCNu32, &year, &week, &day); if (rc == 3) { if ((week < 1U) || (week > crm_time_weeks_in_year(year))) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid week of year %" PRIu32 " (1-%d)", date_str, week, year, crm_time_weeks_in_year(year)); goto invalid; } else if ((day < 1U) || (day > 7U)) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification " "because '%" PRIu32 "' is not a valid day of the week", date_str, day); goto invalid; } else { /* * See https://en.wikipedia.org/wiki/ISO_week_date * * Monday 29 December 2008 is written "2009-W01-1" * Sunday 3 January 2010 is written "2009-W53-7" * Saturday 27 September 2008 is written "2008-W37-6" * * If 1 January is on a Monday, Tuesday, Wednesday or Thursday, it * is in week 1. If 1 January is on a Friday, Saturday or Sunday, * it is in week 52 or 53 of the previous year. */ int jan1 = crm_time_january1_weekday(year); crm_trace("Parsed year %" PRIu32 " (Jan 1 = %d), week %" PRIu32 ", and day %" PRIu32 " from date string '%s'", year, jan1, week, day, date_str); dt->years = year; crm_time_add_days(dt, (week - 1) * 7); if (jan1 <= 4) { crm_time_add_days(dt, 1 - jan1); } else { crm_time_add_days(dt, 8 - jan1); } crm_time_add_days(dt, day); } goto parse_time; } pcmk__err("'%s' is not a valid ISO 8601 date/time specification", date_str); goto invalid; parse_time: if (time_s == NULL) { time_s = date_str + strspn(date_str, "0123456789-W"); if ((time_s[0] == ' ') || (time_s[0] == 'T')) { ++time_s; } else { time_s = NULL; } } if ((time_s != NULL) && (crm_time_parse(time_s, dt) == FALSE)) { goto invalid; } crm_time_log(LOG_TRACE, "Unpacked", dt, crm_time_log_date | crm_time_log_timeofday); if (crm_time_check(dt) == FALSE) { pcmk__err("'%s' is not a valid ISO 8601 date/time specification", date_str); goto invalid; } return dt; invalid: crm_time_free(dt); errno = EINVAL; return NULL; } // Parse an ISO 8601 numeric value and return number of characters consumed static int parse_int(const char *str, int *result) { unsigned int lpc; int offset = (str[0] == 'T')? 1 : 0; bool negate = false; *result = 0; // @TODO This cannot handle combinations of these characters switch (str[offset]) { case '.': case ',': return 0; // Fractions are not supported case '-': negate = true; offset++; break; case '+': case ':': offset++; break; default: break; } for (lpc = 0; (lpc < 10) && isdigit(str[offset]); lpc++) { const int digit = str[offset++] - '0'; if ((*result * 10LL + digit) > INT_MAX) { return 0; // Overflow } *result = *result * 10 + digit; } if (negate) { *result = 0 - *result; } return (lpc > 0)? offset : 0; } /*! * \brief Parse a time duration from an ISO 8601 duration specification * * \param[in] period_s ISO 8601 duration specification (optionally followed by * whitespace, after which the rest of the string will be * ignored) * * \return New time object on success, NULL (and set errno) otherwise * \note It is the caller's responsibility to return the result using * crm_time_free(). */ crm_time_t * crm_time_parse_duration(const char *period_s) { gboolean is_time = FALSE; crm_time_t *diff = NULL; if (pcmk__str_empty(period_s)) { pcmk__err("No ISO 8601 time duration given"); goto invalid; } if (period_s[0] != 'P') { pcmk__err("'%s' is not a valid ISO 8601 time duration because it does " "not start with a 'P'", period_s); goto invalid; } if ((period_s[1] == '\0') || isspace(period_s[1])) { pcmk__err("'%s' is not a valid ISO 8601 time duration because nothing " "follows 'P'", period_s); goto invalid; } diff = crm_time_new_undefined(); for (const char *current = period_s + 1; current[0] && (current[0] != '/') && !isspace(current[0]); ++current) { int an_int = 0, rc; long long result = 0LL; if (current[0] == 'T') { /* A 'T' separates year/month/day from hour/minute/seconds. We don't * require it strictly, but just use it to differentiate month from * minutes. */ is_time = TRUE; continue; } // An integer must be next rc = parse_int(current, &an_int); if (rc == 0) { pcmk__err("'%s' is not a valid ISO 8601 time duration because no " "valid integer at '%s'", period_s, current); goto invalid; } current += rc; // A time unit must be next (we're not strict about the order) switch (current[0]) { case 'Y': diff->years = an_int; break; case 'M': if (!is_time) { // Months diff->months = an_int; } else { // Minutes result = diff->seconds + an_int * 60LL; if ((result < INT_MIN) || (result > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 time duration " "because integer at '%s' is too %s", period_s, (current - rc), ((result > 0)? "large" : "small")); goto invalid; } else { diff->seconds = (int) result; } } break; case 'W': result = diff->days + an_int * 7LL; if ((result < INT_MIN) || (result > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 time duration " "because integer at '%s' is too %s", period_s, (current - rc), ((result > 0)? "large" : "small")); goto invalid; } else { diff->days = (int) result; } break; case 'D': result = diff->days + (long long) an_int; if ((result < INT_MIN) || (result > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 time duration " "because integer at '%s' is too %s", period_s, (current - rc), ((result > 0)? "large" : "small")); goto invalid; } else { diff->days = (int) result; } break; case 'H': result = diff->seconds + (long long) an_int * HOUR_SECONDS; if ((result < INT_MIN) || (result > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 time duration " "because integer at '%s' is too %s", period_s, (current - rc), ((result > 0)? "large" : "small")); goto invalid; } else { diff->seconds = (int) result; } break; case 'S': result = diff->seconds + (long long) an_int; if ((result < INT_MIN) || (result > INT_MAX)) { pcmk__err("'%s' is not a valid ISO 8601 time duration " "because integer at '%s' is too %s", period_s, (current - rc), ((result > 0)? "large" : "small")); goto invalid; } else { diff->seconds = (int) result; } break; case '\0': pcmk__err("'%s' is not a valid ISO 8601 time duration because " "no units after %d", period_s, an_int); goto invalid; default: pcmk__err("'%s' is not a valid ISO 8601 time duration because " "'%c' is not a valid time unit", period_s, current[0]); goto invalid; } } if (!crm_time_is_defined(diff)) { pcmk__err("'%s' is not a valid ISO 8601 time duration because no " "amounts and units given", period_s); goto invalid; } diff->duration = TRUE; return diff; invalid: crm_time_free(diff); errno = EINVAL; return NULL; } /*! * \brief Parse a time period from an ISO 8601 interval specification * * \param[in] period_str ISO 8601 interval specification (start/end, * start/duration, or duration/end) * * \return New time period object on success, NULL (and set errno) otherwise * \note The caller is responsible for freeing the result using * crm_time_free_period(). */ crm_time_period_t * crm_time_parse_period(const char *period_str) { const char *original = period_str; crm_time_period_t *period = NULL; if (pcmk__str_empty(period_str)) { pcmk__err("No ISO 8601 time period given"); goto invalid; } tzset(); period = pcmk__assert_alloc(1, sizeof(crm_time_period_t)); if (period_str[0] == 'P') { period->diff = crm_time_parse_duration(period_str); if (period->diff == NULL) { goto error; } } else { period->start = parse_date(period_str); if (period->start == NULL) { goto error; } } period_str = strstr(original, "/"); if (period_str) { ++period_str; if (period_str[0] == 'P') { if (period->diff != NULL) { pcmk__err("'%s' is not a valid ISO 8601 time period because it " "has two durations", original); goto invalid; } period->diff = crm_time_parse_duration(period_str); if (period->diff == NULL) { goto error; } } else { period->end = parse_date(period_str); if (period->end == NULL) { goto error; } } } else if (period->diff != NULL) { // Only duration given, assume start is now period->start = crm_time_new(NULL); } else { // Only start given pcmk__err("'%s' is not a valid ISO 8601 time period because it has no " "duration or ending time", original); goto invalid; } if (period->start == NULL) { period->start = crm_time_subtract(period->end, period->diff); } else if (period->end == NULL) { period->end = crm_time_add(period->start, period->diff); } if (crm_time_check(period->start) == FALSE) { pcmk__err("'%s' is not a valid ISO 8601 time period because the start " "is invalid", period_str); goto invalid; } if (crm_time_check(period->end) == FALSE) { pcmk__err("'%s' is not a valid ISO 8601 time period because the end is " "invalid", period_str); goto invalid; } return period; invalid: errno = EINVAL; error: crm_time_free_period(period); return NULL; } /*! * \brief Free a dynamically allocated time period object * * \param[in,out] period Time period to free */ void crm_time_free_period(crm_time_period_t *period) { if (period) { crm_time_free(period->start); crm_time_free(period->end); crm_time_free(period->diff); free(period); } } void crm_time_set(crm_time_t *target, const crm_time_t *source) { crm_trace("target=%p, source=%p", target, source); CRM_CHECK(target != NULL && source != NULL, return); target->years = source->years; target->days = source->days; target->months = source->months; /* Only for durations */ target->seconds = source->seconds; target->offset = source->offset; crm_time_log(LOG_TRACE, "source", source, crm_time_log_date | crm_time_log_timeofday | crm_time_log_with_timezone); crm_time_log(LOG_TRACE, "target", target, crm_time_log_date | crm_time_log_timeofday | crm_time_log_with_timezone); } static void ha_set_tm_time(crm_time_t *target, const struct tm *source) { int h_offset = 0; int m_offset = 0; /* Ensure target is fully initialized */ target->years = 0; target->months = 0; target->days = 0; target->seconds = 0; target->offset = 0; target->duration = FALSE; if (source->tm_year > 0) { /* years since 1900 */ target->years = 1900; crm_time_add_years(target, source->tm_year); } if (source->tm_yday >= 0) { /* days since January 1 [0-365] */ target->days = 1 + source->tm_yday; } if (source->tm_hour >= 0) { target->seconds += HOUR_SECONDS * source->tm_hour; } if (source->tm_min >= 0) { target->seconds += 60 * source->tm_min; } if (source->tm_sec >= 0) { target->seconds += source->tm_sec; } /* tm_gmtoff == offset from UTC in seconds */ h_offset = GMTOFF(source) / HOUR_SECONDS; m_offset = (GMTOFF(source) - (HOUR_SECONDS * h_offset)) / 60; crm_trace("Time offset is %lds (%.2d:%.2d)", GMTOFF(source), h_offset, m_offset); target->offset += HOUR_SECONDS * h_offset; target->offset += 60 * m_offset; } void crm_time_set_timet(crm_time_t *target, const time_t *source) { ha_set_tm_time(target, localtime(source)); } /*! * \internal * \brief Set one time object to another if the other is earlier * * \param[in,out] target Time object to set * \param[in] source Time object to use if earlier */ void pcmk__set_time_if_earlier(crm_time_t *target, const crm_time_t *source) { if ((target != NULL) && (source != NULL) && (!crm_time_is_defined(target) || (crm_time_compare(source, target) < 0))) { crm_time_set(target, source); } } crm_time_t * pcmk_copy_time(const crm_time_t *source) { crm_time_t *target = crm_time_new_undefined(); crm_time_set(target, source); return target; } /*! * \internal * \brief Convert a \p time_t time to a \p crm_time_t time * * \param[in] source Time to convert * * \return A \p crm_time_t object representing \p source */ crm_time_t * pcmk__copy_timet(time_t source) { crm_time_t *target = crm_time_new_undefined(); crm_time_set_timet(target, &source); return target; } crm_time_t * crm_time_add(const crm_time_t *dt, const crm_time_t *value) { crm_time_t *utc = NULL; crm_time_t *answer = NULL; if ((dt == NULL) || (value == NULL)) { errno = EINVAL; return NULL; } answer = pcmk_copy_time(dt); utc = crm_get_utc_time(value); if (utc == NULL) { crm_time_free(answer); return NULL; } crm_time_add_years(answer, utc->years); crm_time_add_months(answer, utc->months); crm_time_add_days(answer, utc->days); crm_time_add_seconds(answer, utc->seconds); crm_time_free(utc); return answer; } /*! * \internal * \brief Return the XML attribute name corresponding to a time component * * \param[in] component Component to check * * \return XML attribute name corresponding to \p component, or NULL if * \p component is invalid */ const char * pcmk__time_component_attr(enum pcmk__time_component component) { switch (component) { case pcmk__time_years: return PCMK_XA_YEARS; case pcmk__time_months: return PCMK_XA_MONTHS; case pcmk__time_weeks: return PCMK_XA_WEEKS; case pcmk__time_days: return PCMK_XA_DAYS; case pcmk__time_hours: return PCMK_XA_HOURS; case pcmk__time_minutes: return PCMK_XA_MINUTES; case pcmk__time_seconds: return PCMK_XA_SECONDS; default: return NULL; } } typedef void (*component_fn_t)(crm_time_t *, int); /*! * \internal * \brief Get the addition function corresponding to a time component * \param[in] component Component to check * * \return Addition function corresponding to \p component, or NULL if * \p component is invalid */ static component_fn_t component_fn(enum pcmk__time_component component) { switch (component) { case pcmk__time_years: return crm_time_add_years; case pcmk__time_months: return crm_time_add_months; case pcmk__time_weeks: return crm_time_add_weeks; case pcmk__time_days: return crm_time_add_days; case pcmk__time_hours: return crm_time_add_hours; case pcmk__time_minutes: return crm_time_add_minutes; case pcmk__time_seconds: return crm_time_add_seconds; default: return NULL; } } /*! * \internal * \brief Add the value of an XML attribute to a time object * * \param[in,out] t Time object to add to * \param[in] component Component of \p t to add to * \param[in] xml XML with value to add * * \return Standard Pacemaker return code */ int pcmk__add_time_from_xml(crm_time_t *t, enum pcmk__time_component component, const xmlNode *xml) { long long value; const char *attr = pcmk__time_component_attr(component); component_fn_t add = component_fn(component); if ((t == NULL) || (attr == NULL) || (add == NULL)) { return EINVAL; } if (xml == NULL) { return pcmk_rc_ok; } if (pcmk__scan_ll(pcmk__xe_get(xml, attr), &value, 0LL) != pcmk_rc_ok) { return pcmk_rc_unpack_error; } if ((value < INT_MIN) || (value > INT_MAX)) { return ERANGE; } if (value != 0LL) { add(t, (int) value); } return pcmk_rc_ok; } crm_time_t * crm_time_calculate_duration(const crm_time_t *dt, const crm_time_t *value) { crm_time_t *utc = NULL; crm_time_t *answer = NULL; if ((dt == NULL) || (value == NULL)) { errno = EINVAL; return NULL; } utc = crm_get_utc_time(value); if (utc == NULL) { return NULL; } answer = crm_get_utc_time(dt); if (answer == NULL) { crm_time_free(utc); return NULL; } answer->duration = TRUE; crm_time_add_years(answer, -utc->years); if(utc->months != 0) { crm_time_add_months(answer, -utc->months); } crm_time_add_days(answer, -utc->days); crm_time_add_seconds(answer, -utc->seconds); crm_time_free(utc); return answer; } crm_time_t * crm_time_subtract(const crm_time_t *dt, const crm_time_t *value) { crm_time_t *utc = NULL; crm_time_t *answer = NULL; if ((dt == NULL) || (value == NULL)) { errno = EINVAL; return NULL; } utc = crm_get_utc_time(value); if (utc == NULL) { return NULL; } answer = pcmk_copy_time(dt); crm_time_add_years(answer, -utc->years); if(utc->months != 0) { crm_time_add_months(answer, -utc->months); } crm_time_add_days(answer, -utc->days); crm_time_add_seconds(answer, -utc->seconds); crm_time_free(utc); return answer; } /*! * \brief Check whether a time object represents a sensible date/time * * \param[in] dt Date/time object to check * * \return \c true if years, days, and seconds are sensible, \c false otherwise */ bool crm_time_check(const crm_time_t *dt) { return (dt != NULL) && (dt->days > 0) && (dt->days <= year_days(dt->years)) && (dt->seconds >= 0) && (dt->seconds < DAY_SECONDS); } #define do_cmp_field(l, r, field) \ if(rc == 0) { \ if(l->field > r->field) { \ crm_trace("%s: %d > %d", \ #field, l->field, r->field); \ rc = 1; \ } else if(l->field < r->field) { \ crm_trace("%s: %d < %d", \ #field, l->field, r->field); \ rc = -1; \ } \ } int crm_time_compare(const crm_time_t *a, const crm_time_t *b) { int rc = 0; crm_time_t *t1 = crm_get_utc_time(a); crm_time_t *t2 = crm_get_utc_time(b); if ((t1 == NULL) && (t2 == NULL)) { rc = 0; } else if (t1 == NULL) { rc = -1; } else if (t2 == NULL) { rc = 1; } else { do_cmp_field(t1, t2, years); do_cmp_field(t1, t2, days); do_cmp_field(t1, t2, seconds); } crm_time_free(t1); crm_time_free(t2); return rc; } /*! * \brief Add a given number of seconds to a date/time or duration * * \param[in,out] a_time Date/time or duration to add seconds to * \param[in] extra Number of seconds to add */ void crm_time_add_seconds(crm_time_t *a_time, int extra) { int days = extra / DAY_SECONDS; pcmk__assert(a_time != NULL); crm_trace("Adding %d seconds (including %d whole day%s) to %d", extra, days, pcmk__plural_s(days), a_time->seconds); a_time->seconds += extra % DAY_SECONDS; // Check whether the addition crossed a day boundary if (a_time->seconds > DAY_SECONDS) { ++days; a_time->seconds -= DAY_SECONDS; } else if (a_time->seconds < 0) { --days; a_time->seconds += DAY_SECONDS; } crm_time_add_days(a_time, days); } #define ydays(t) (crm_time_leapyear((t)->years)? 366 : 365) /*! * \brief Add days to a date/time * * \param[in,out] a_time Time to modify * \param[in] extra Number of days to add (may be negative to subtract) */ void crm_time_add_days(crm_time_t *a_time, int extra) { pcmk__assert(a_time != NULL); crm_trace("Adding %d days to %.4d-%.3d", extra, a_time->years, a_time->days); if (extra > 0) { while ((a_time->days + (long long) extra) > ydays(a_time)) { if ((a_time->years + 1LL) > INT_MAX) { a_time->days = ydays(a_time); // Clip to latest we can handle return; } extra -= ydays(a_time); a_time->years++; } } else if (extra < 0) { const int min_days = a_time->duration? 0 : 1; while ((a_time->days + (long long) extra) < min_days) { if ((a_time->years - 1) < 1) { a_time->days = 1; // Clip to earliest we can handle (no BCE) return; } a_time->years--; extra += ydays(a_time); } } a_time->days += extra; } void crm_time_add_months(crm_time_t * a_time, int extra) { int lpc; uint32_t y, m, d, dmax; crm_time_get_gregorian(a_time, &y, &m, &d); crm_trace("Adding %d months to %.4" PRIu32 "-%.2" PRIu32 "-%.2" PRIu32, extra, y, m, d); if (extra > 0) { for (lpc = extra; lpc > 0; lpc--) { m++; if (m == 13) { m = 1; y++; } } } else { for (lpc = -extra; lpc > 0; lpc--) { m--; if (m == 0) { m = 12; y--; } } } dmax = crm_time_days_in_month(m, y); if (dmax < d) { /* Preserve day-of-month unless the month doesn't have enough days */ d = dmax; } crm_trace("Calculated %.4" PRIu32 "-%.2" PRIu32 "-%.2" PRIu32, y, m, d); a_time->years = y; a_time->days = get_ordinal_days(y, m, d); crm_time_get_gregorian(a_time, &y, &m, &d); crm_trace("Got %.4" PRIu32 "-%.2" PRIu32 "-%.2" PRIu32, y, m, d); } void crm_time_add_minutes(crm_time_t * a_time, int extra) { crm_time_add_seconds(a_time, extra * 60); } void crm_time_add_hours(crm_time_t * a_time, int extra) { crm_time_add_seconds(a_time, extra * HOUR_SECONDS); } void crm_time_add_weeks(crm_time_t * a_time, int extra) { crm_time_add_days(a_time, extra * 7); } void crm_time_add_years(crm_time_t * a_time, int extra) { pcmk__assert(a_time != NULL); if ((extra > 0) && ((a_time->years + (long long) extra) > INT_MAX)) { a_time->years = INT_MAX; } else if ((extra < 0) && ((a_time->years + (long long) extra) < 1)) { a_time->years = 1; // Clip to earliest we can handle (no BCE) } else { a_time->years += extra; } } static void ha_get_tm_time(struct tm *target, const crm_time_t *source) { *target = (struct tm) { .tm_year = source->years - 1900, .tm_mday = source->days, .tm_sec = source->seconds % 60, .tm_min = ( source->seconds / 60 ) % 60, .tm_hour = source->seconds / HOUR_SECONDS, .tm_isdst = -1, /* don't adjust */ #if defined(HAVE_STRUCT_TM_TM_GMTOFF) .tm_gmtoff = source->offset #endif }; mktime(target); } /* The high-resolution variant of time object was added to meet an immediate * need, and is kept internal API. * * @TODO The long-term goal is to come up with a clean, unified design for a * time type (or types) that meets all the various needs, to replace * crm_time_t, pcmk__time_hr_t, and struct timespec (in lrmd_cmd_t). */ pcmk__time_hr_t * pcmk__time_hr_convert(pcmk__time_hr_t *target, const crm_time_t *dt) { pcmk__time_hr_t *hr_dt = NULL; if (dt) { hr_dt = target; if (hr_dt == NULL) { hr_dt = pcmk__assert_alloc(1, sizeof(pcmk__time_hr_t)); } *hr_dt = (pcmk__time_hr_t) { .years = dt->years, .months = dt->months, .days = dt->days, .seconds = dt->seconds, .offset = dt->offset, .duration = dt->duration }; } return hr_dt; } void pcmk__time_set_hr_dt(crm_time_t *target, const pcmk__time_hr_t *hr_dt) { pcmk__assert((target != NULL) && (hr_dt != NULL)); *target = (crm_time_t) { .years = hr_dt->years, .months = hr_dt->months, .days = hr_dt->days, .seconds = hr_dt->seconds, .offset = hr_dt->offset, .duration = hr_dt->duration }; } /*! * \internal * \brief Return the current time as a high-resolution time * * \param[out] epoch If not NULL, this will be set to seconds since epoch * * \return Newly allocated high-resolution time set to the current time */ pcmk__time_hr_t * pcmk__time_hr_now(time_t *epoch) { struct timespec tv; crm_time_t dt; pcmk__time_hr_t *hr; qb_util_timespec_from_epoch_get(&tv); if (epoch != NULL) { *epoch = tv.tv_sec; } crm_time_set_timet(&dt, &(tv.tv_sec)); hr = pcmk__time_hr_convert(NULL, &dt); if (hr != NULL) { hr->useconds = tv.tv_nsec / QB_TIME_NS_IN_USEC; } return hr; } pcmk__time_hr_t * pcmk__time_hr_new(const char *date_time) { pcmk__time_hr_t *hr_dt = NULL; if (date_time == NULL) { hr_dt = pcmk__time_hr_now(NULL); } else { crm_time_t *dt; dt = parse_date(date_time); hr_dt = pcmk__time_hr_convert(NULL, dt); crm_time_free(dt); } return hr_dt; } void pcmk__time_hr_free(pcmk__time_hr_t * hr_dt) { free(hr_dt); } /*! * \internal * \brief Expand a date/time format string, including %N for nanoseconds * * \param[in] format Date/time format string as per strftime(3) with the * addition of %N for nanoseconds * \param[in] hr_dt Time value to format * * \return Newly allocated string with formatted string */ char * pcmk__time_format_hr(const char *format, const pcmk__time_hr_t *hr_dt) { int scanned_pos = 0; // How many characters of format have been parsed int printed_pos = 0; // How many characters of format have been processed size_t date_len = 0; char nano_s[10] = { '\0', }; char date_s[128] = { '\0', }; struct tm tm = { 0, }; crm_time_t dt = { 0, }; if (format == NULL) { return NULL; } pcmk__time_set_hr_dt(&dt, hr_dt); ha_get_tm_time(&tm, &dt); sprintf(nano_s, "%06d000", hr_dt->useconds); while (format[scanned_pos] != '\0') { int fmt_pos; // Index after last character to pass as-is int nano_digits = 0; // Length of %N field width (if any) char *tmp_fmt_s = NULL; size_t nbytes = 0; // Look for next format specifier const char *mark_s = strchr(&format[scanned_pos], '%'); if (mark_s == NULL) { // No more specifiers, so pass remaining string to strftime() as-is scanned_pos = strlen(format); fmt_pos = scanned_pos; } else { fmt_pos = mark_s - format; // Index of % // Skip % and any field width scanned_pos = fmt_pos + 1; while (isdigit(format[scanned_pos])) { scanned_pos++; } switch (format[scanned_pos]) { case '\0': // Literal % and possibly digits at end of string fmt_pos = scanned_pos; // Pass remaining string as-is break; case 'N': // %[width]N scanned_pos++; // Parse field width nano_digits = atoi(&format[fmt_pos + 1]); nano_digits = QB_MAX(nano_digits, 0); nano_digits = QB_MIN(nano_digits, 6); break; default: // Some other specifier if (format[++scanned_pos] != '\0') { // More to parse continue; } fmt_pos = scanned_pos; // Pass remaining string as-is break; } } if (date_len >= sizeof(date_s)) { return NULL; // No room for remaining string } tmp_fmt_s = strndup(&format[printed_pos], fmt_pos - printed_pos); #ifdef HAVE_FORMAT_NONLITERAL #pragma GCC diagnostic push #pragma GCC diagnostic ignored "-Wformat-nonliteral" #endif nbytes = strftime(&date_s[date_len], sizeof(date_s) - date_len, tmp_fmt_s, &tm); #ifdef HAVE_FORMAT_NONLITERAL #pragma GCC diagnostic pop #endif free(tmp_fmt_s); if (nbytes == 0) { // Would overflow buffer return NULL; } date_len += nbytes; printed_pos = scanned_pos; if (nano_digits != 0) { int nc = 0; if (date_len >= sizeof(date_s)) { return NULL; // No room to add nanoseconds } nc = snprintf(&date_s[date_len], sizeof(date_s) - date_len, "%.*s", nano_digits, nano_s); if ((nc < 0) || (nc == (sizeof(date_s) - date_len))) { return NULL; // Error or would overflow buffer } date_len += nc; } } return (date_len == 0)? NULL : pcmk__str_copy(date_s); } /*! * \internal * \brief Return a human-friendly string corresponding to an epoch time value * * \param[in] source Pointer to epoch time value (or \p NULL for current time) * \param[in] flags Group of \p crm_time_* flags controlling display format * (0 to use \p ctime() with newline removed) * * \return String representation of \p source on success (may be empty depending * on \p flags; guaranteed not to be \p NULL) * * \note The caller is responsible for freeing the return value using \p free(). */ char * pcmk__epoch2str(const time_t *source, uint32_t flags) { time_t epoch_time = (source == NULL)? time(NULL) : *source; if (flags == 0) { return pcmk__str_copy(pcmk__trim(ctime(&epoch_time))); } else { crm_time_t dt; crm_time_set_timet(&dt, &epoch_time); return crm_time_as_string(&dt, flags); } } /*! * \internal * \brief Return a human-friendly string corresponding to seconds-and- * nanoseconds value * * Time is shown with microsecond resolution if \p crm_time_usecs is in \p * flags. * * \param[in] ts Time in seconds and nanoseconds (or \p NULL for current * time) * \param[in] flags Group of \p crm_time_* flags controlling display format * * \return String representation of \p ts on success (may be empty depending on * \p flags; guaranteed not to be \p NULL) * * \note The caller is responsible for freeing the return value using \p free(). */ char * pcmk__timespec2str(const struct timespec *ts, uint32_t flags) { struct timespec tmp_ts; crm_time_t dt; char result[DATE_MAX] = { 0 }; if (ts == NULL) { qb_util_timespec_from_epoch_get(&tmp_ts); ts = &tmp_ts; } crm_time_set_timet(&dt, &ts->tv_sec); time_as_string_common(&dt, ts->tv_nsec / QB_TIME_NS_IN_USEC, flags, result); return pcmk__str_copy(result); } /*! * \internal * \brief Given a millisecond interval, return a log-friendly string * * \param[in] interval_ms Interval in milliseconds * * \return Readable version of \p interval_ms * * \note The return value is a pointer to static memory that will be * overwritten by later calls to this function. */ const char * pcmk__readable_interval(guint interval_ms) { #define MS_IN_S (1000) #define MS_IN_M (MS_IN_S * 60) #define MS_IN_H (MS_IN_M * 60) #define MS_IN_D (MS_IN_H * 24) #define MAXSTR sizeof("..d..h..m..s...ms") static char str[MAXSTR]; int offset = 0; str[0] = '\0'; if (interval_ms >= MS_IN_D) { offset += snprintf(str + offset, MAXSTR - offset, "%ud", interval_ms / MS_IN_D); interval_ms -= (interval_ms / MS_IN_D) * MS_IN_D; } if (interval_ms >= MS_IN_H) { offset += snprintf(str + offset, MAXSTR - offset, "%uh", interval_ms / MS_IN_H); interval_ms -= (interval_ms / MS_IN_H) * MS_IN_H; } if (interval_ms >= MS_IN_M) { offset += snprintf(str + offset, MAXSTR - offset, "%um", interval_ms / MS_IN_M); interval_ms -= (interval_ms / MS_IN_M) * MS_IN_M; } // Ns, N.NNNs, or NNNms if (interval_ms >= MS_IN_S) { offset += snprintf(str + offset, MAXSTR - offset, "%u", interval_ms / MS_IN_S); interval_ms -= (interval_ms / MS_IN_S) * MS_IN_S; if (interval_ms > 0) { offset += snprintf(str + offset, MAXSTR - offset, ".%03u", interval_ms); } (void) snprintf(str + offset, MAXSTR - offset, "s"); } else if (interval_ms > 0) { (void) snprintf(str + offset, MAXSTR - offset, "%ums", interval_ms); } else if (str[0] == '\0') { strcpy(str, "0s"); } return str; } diff --git a/lib/common/logging.c b/lib/common/logging.c index ef0c0518cf..23e43f63a1 100644 --- a/lib/common/logging.c +++ b/lib/common/logging.c @@ -1,1303 +1,1303 @@ /* * Copyright 2004-2025 the Pacemaker project contributors * * The version control history for this file may have further details. * * This source code is licensed under the GNU Lesser General Public License * version 2.1 or later (LGPLv2.1+) WITHOUT ANY WARRANTY. */ #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include // Use high-resolution (millisecond) timestamps if libqb supports them #ifdef QB_FEATURE_LOG_HIRES_TIMESTAMPS #define TIMESTAMP_FORMAT_SPEC "%%T" typedef struct timespec *log_time_t; #else #define TIMESTAMP_FORMAT_SPEC "%%t" typedef time_t log_time_t; #endif unsigned int crm_log_level = LOG_INFO; unsigned int crm_trace_nonlog = 0; bool pcmk__is_daemon = false; static unsigned int crm_log_priority = LOG_NOTICE; static guint pcmk__log_id = 0; static guint pcmk__glib_log_id = 0; static guint pcmk__gio_log_id = 0; static guint pcmk__gmodule_log_id = 0; static guint pcmk__gthread_log_id = 0; static pcmk__output_t *logger_out = NULL; pcmk__config_error_func pcmk__config_error_handler = NULL; pcmk__config_warning_func pcmk__config_warning_handler = NULL; void *pcmk__config_error_context = NULL; void *pcmk__config_warning_context = NULL; static gboolean crm_tracing_enabled(void); static void crm_glib_handler(const gchar * log_domain, GLogLevelFlags flags, const gchar * message, gpointer user_data) { int log_level = LOG_WARNING; GLogLevelFlags msg_level = (flags & G_LOG_LEVEL_MASK); static struct qb_log_callsite *glib_cs = NULL; if (glib_cs == NULL) { glib_cs = qb_log_callsite_get(__func__, __FILE__, "glib-handler", LOG_DEBUG, __LINE__, crm_trace_nonlog); } switch (msg_level) { case G_LOG_LEVEL_CRITICAL: log_level = LOG_CRIT; if (!crm_is_callsite_active(glib_cs, LOG_DEBUG, crm_trace_nonlog)) { /* log and record how we got here */ crm_abort(__FILE__, __func__, __LINE__, message, TRUE, TRUE); } break; case G_LOG_LEVEL_ERROR: log_level = LOG_ERR; break; case G_LOG_LEVEL_MESSAGE: log_level = LOG_NOTICE; break; case G_LOG_LEVEL_INFO: log_level = LOG_INFO; break; case G_LOG_LEVEL_DEBUG: log_level = LOG_DEBUG; break; case G_LOG_LEVEL_WARNING: case G_LOG_FLAG_RECURSION: case G_LOG_FLAG_FATAL: case G_LOG_LEVEL_MASK: log_level = LOG_WARNING; break; } do_crm_log(log_level, "%s: %s", log_domain, message); } #ifndef NAME_MAX # define NAME_MAX 256 #endif /*! * \internal * \brief Write out a blackbox (enabling blackboxes if needed) * * \param[in] nsig Signal number that was received * * \note This is a true signal handler, and so must be async-safe. */ static void crm_trigger_blackbox(int nsig) { if(nsig == SIGTRAP) { /* Turn it on if it wasn't already */ crm_enable_blackbox(nsig); } crm_write_blackbox(nsig, NULL); } void crm_log_deinit(void) { if (pcmk__log_id == 0) { return; } g_log_remove_handler(G_LOG_DOMAIN, pcmk__log_id); pcmk__log_id = 0; g_log_remove_handler("GLib", pcmk__glib_log_id); pcmk__glib_log_id = 0; g_log_remove_handler("GLib-GIO", pcmk__gio_log_id); pcmk__gio_log_id = 0; g_log_remove_handler("GModule", pcmk__gmodule_log_id); pcmk__gmodule_log_id = 0; g_log_remove_handler("GThread", pcmk__gthread_log_id); pcmk__gthread_log_id = 0; } #define FMT_MAX 256 /*! * \internal * \brief Set the log format string based on the passed-in method * * \param[in] method The detail level of the log output * \param[in] daemon The daemon ID included in error messages * \param[in] use_pid Cached result of getpid() call, for efficiency * \param[in] use_nodename Cached result of uname() call, for efficiency * */ /* XXX __attribute__((nonnull)) for use_nodename parameter */ static void set_format_string(int method, const char *daemon, pid_t use_pid, const char *use_nodename) { if (method == QB_LOG_SYSLOG) { // The system log gets a simplified, user-friendly format qb_log_ctl(method, QB_LOG_CONF_EXTENDED, QB_FALSE); qb_log_format_set(method, "%g %p: %b"); } else { // Everything else gets more detail, for advanced troubleshooting int offset = 0; char fmt[FMT_MAX]; if (method > QB_LOG_STDERR) { // If logging to file, prefix with timestamp, node name, daemon ID offset += snprintf(fmt + offset, FMT_MAX - offset, TIMESTAMP_FORMAT_SPEC " %s %-20s[%lu] ", use_nodename, daemon, (unsigned long) use_pid); } // Add function name (in parentheses) offset += snprintf(fmt + offset, FMT_MAX - offset, "(%%n"); if (crm_tracing_enabled()) { // When tracing, add file and line number offset += snprintf(fmt + offset, FMT_MAX - offset, "@%%f:%%l"); } offset += snprintf(fmt + offset, FMT_MAX - offset, ")"); // Add tag (if any), severity, and actual message offset += snprintf(fmt + offset, FMT_MAX - offset, " %%g\t%%p: %%b"); CRM_LOG_ASSERT(offset > 0); qb_log_format_set(method, fmt); } } #define DEFAULT_LOG_FILE CRM_LOG_DIR "/pacemaker.log" static bool logfile_disabled(const char *filename) { return pcmk__str_eq(filename, PCMK_VALUE_NONE, pcmk__str_casei) || pcmk__str_eq(filename, "/dev/null", pcmk__str_none); } /*! * \internal * \brief Fix log file ownership if group is wrong or doesn't have access * * \param[in] filename Log file name (for logging only) * \param[in] logfd Log file descriptor * * \return Standard Pacemaker return code */ static int chown_logfile(const char *filename, int logfd) { uid_t pcmk_uid = 0; gid_t pcmk_gid = 0; struct stat st; int rc = pcmk_rc_ok; // Get the log file's current ownership and permissions if (fstat(logfd, &st) < 0) { return errno; } // Any other errors don't prevent file from being used as log rc = pcmk__daemon_user(&pcmk_uid, &pcmk_gid); if (rc != pcmk_rc_ok) { pcmk__warn("Not changing '%s' ownership because user information " "unavailable: %s", filename, pcmk_rc_str(rc)); return pcmk_rc_ok; } if ((st.st_gid == pcmk_gid) && ((st.st_mode & S_IRWXG) == (S_IRGRP|S_IWGRP))) { return pcmk_rc_ok; } if (fchown(logfd, pcmk_uid, pcmk_gid) < 0) { pcmk__warn("Couldn't change '%s' ownership to user %s gid %d: %s", filename, CRM_DAEMON_USER, pcmk_gid, strerror(errno)); } return pcmk_rc_ok; } // Reset log file permissions (using environment variable if set) static void chmod_logfile(const char *filename, int logfd) { const char *modestr = pcmk__env_option(PCMK__ENV_LOGFILE_MODE); mode_t filemode = S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP; if (modestr != NULL) { long filemode_l = strtol(modestr, NULL, 8); if ((filemode_l != LONG_MIN) && (filemode_l != LONG_MAX)) { filemode = (mode_t) filemode_l; } } if ((filemode != 0) && (fchmod(logfd, filemode) < 0)) { pcmk__warn("Couldn't change '%s' mode to %04o: %s", filename, filemode, strerror(errno)); } } // If we're root, correct a log file's permissions if needed static int set_logfile_permissions(const char *filename, FILE *logfile) { if (geteuid() == 0) { int logfd = fileno(logfile); int rc = chown_logfile(filename, logfd); if (rc != pcmk_rc_ok) { return rc; } chmod_logfile(filename, logfd); } return pcmk_rc_ok; } // Enable libqb logging to a new log file static void enable_logfile(int fd) { qb_log_ctl(fd, QB_LOG_CONF_ENABLED, QB_TRUE); #if 0 qb_log_ctl(fd, QB_LOG_CONF_FILE_SYNC, 1); // Turn on synchronous writes #endif #ifdef HAVE_qb_log_conf_QB_LOG_CONF_MAX_LINE_LEN // Longer than default, for logging long XML lines qb_log_ctl(fd, QB_LOG_CONF_MAX_LINE_LEN, 800); #endif crm_update_callsites(); } static inline void disable_logfile(int fd) { qb_log_ctl(fd, QB_LOG_CONF_ENABLED, QB_FALSE); } static void setenv_logfile(const char *filename) { // Some resource agents will log only if environment variable is set if (pcmk__env_option(PCMK__ENV_LOGFILE) == NULL) { pcmk__set_env_option(PCMK__ENV_LOGFILE, filename, true); } } /*! * \brief Add a file to be used as a Pacemaker detail log * * \param[in] filename Name of log file to use * * \return Standard Pacemaker return code */ int pcmk__add_logfile(const char *filename) { /* No log messages from this function will be logged to the new log! * If another target such as syslog has already been added, the messages * should show up there. */ int fd = 0; int rc = pcmk_rc_ok; FILE *logfile = NULL; bool is_default = false; static int default_fd = -1; static bool have_logfile = false; // Use default if caller didn't specify (and we don't already have one) if (filename == NULL) { if (have_logfile) { return pcmk_rc_ok; } filename = DEFAULT_LOG_FILE; } // If the user doesn't want logging, we're done if (logfile_disabled(filename)) { return pcmk_rc_ok; } // If the caller wants the default and we already have it, we're done is_default = pcmk__str_eq(filename, DEFAULT_LOG_FILE, pcmk__str_none); if (is_default && (default_fd >= 0)) { return pcmk_rc_ok; } // Check whether we have write access to the file logfile = fopen(filename, "a"); if (logfile == NULL) { rc = errno; pcmk__warn("Logging to '%s' is disabled: %s " QB_XS " uid=%u gid=%u", filename, strerror(rc), geteuid(), getegid()); return rc; } rc = set_logfile_permissions(filename, logfile); if (rc != pcmk_rc_ok) { pcmk__warn("Logging to '%s' is disabled: %s " QB_XS " permissions", filename, strerror(rc)); fclose(logfile); return rc; } // Close and reopen as libqb logging target fclose(logfile); fd = qb_log_file_open(filename); if (fd < 0) { pcmk__warn("Logging to '%s' is disabled: %s " QB_XS " qb_log_file_open", filename, strerror(-fd)); return -fd; // == +errno } if (is_default) { default_fd = fd; setenv_logfile(filename); } else if (default_fd >= 0) { pcmk__notice("Switching logging to %s", filename); disable_logfile(default_fd); } pcmk__notice("Additional logging available in %s", filename); enable_logfile(fd); have_logfile = true; return pcmk_rc_ok; } /*! * \brief Add multiple additional log files * * \param[in] log_files Array of log files to add * \param[in] out Output object to use for error reporting * * \return Standard Pacemaker return code */ void pcmk__add_logfiles(gchar **log_files, pcmk__output_t *out) { if (log_files == NULL) { return; } for (gchar **fname = log_files; *fname != NULL; fname++) { int rc = pcmk__add_logfile(*fname); if (rc != pcmk_rc_ok) { out->err(out, "Logging to %s is disabled: %s", *fname, pcmk_rc_str(rc)); } } } static int blackbox_trigger = 0; static volatile char *blackbox_file_prefix = NULL; static void blackbox_logger(int32_t t, struct qb_log_callsite *cs, log_time_t timestamp, const char *msg) { if(cs && cs->priority < LOG_ERR) { crm_write_blackbox(SIGTRAP, cs); /* Bypass the over-dumping logic */ } else { crm_write_blackbox(0, cs); } } static void crm_control_blackbox(int nsig, bool enable) { int lpc = 0; if (blackbox_file_prefix == NULL) { pid_t pid = getpid(); blackbox_file_prefix = pcmk__assert_asprintf(CRM_BLACKBOX_DIR "/%s-%lu", crm_system_name, (unsigned long) pid); } if (enable && qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) { qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 5 * 1024 * 1024); /* Any size change drops existing entries */ qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE); /* Setting the size seems to disable it */ /* Enable synchronous logging */ for (lpc = QB_LOG_BLACKBOX; lpc < QB_LOG_TARGET_MAX; lpc++) { qb_log_ctl(lpc, QB_LOG_CONF_FILE_SYNC, QB_TRUE); } pcmk__notice("Initiated blackbox recorder: %s", blackbox_file_prefix); /* Save to disk on abnormal termination */ crm_signal_handler(SIGSEGV, crm_trigger_blackbox); crm_signal_handler(SIGABRT, crm_trigger_blackbox); crm_signal_handler(SIGILL, crm_trigger_blackbox); crm_signal_handler(SIGBUS, crm_trigger_blackbox); crm_signal_handler(SIGFPE, crm_trigger_blackbox); crm_update_callsites(); blackbox_trigger = qb_log_custom_open(blackbox_logger, NULL, NULL, NULL); qb_log_ctl(blackbox_trigger, QB_LOG_CONF_ENABLED, QB_TRUE); crm_trace("Trigger: %d is %d %d", blackbox_trigger, qb_log_ctl(blackbox_trigger, QB_LOG_CONF_STATE_GET, 0), QB_LOG_STATE_ENABLED); crm_update_callsites(); } else if (!enable && qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0) == QB_LOG_STATE_ENABLED) { qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE); /* Disable synchronous logging again when the blackbox is disabled */ for (lpc = QB_LOG_BLACKBOX; lpc < QB_LOG_TARGET_MAX; lpc++) { qb_log_ctl(lpc, QB_LOG_CONF_FILE_SYNC, QB_FALSE); } } } void crm_enable_blackbox(int nsig) { crm_control_blackbox(nsig, TRUE); } void crm_disable_blackbox(int nsig) { crm_control_blackbox(nsig, FALSE); } /*! * \internal * \brief Write out a blackbox, if blackboxes are enabled * * \param[in] nsig Signal that was received * \param[in] cs libqb callsite * * \note This may be called via a true signal handler and so must be async-safe. * @TODO actually make this async-safe */ void crm_write_blackbox(int nsig, const struct qb_log_callsite *cs) { static volatile int counter = 1; static volatile time_t last = 0; char buffer[NAME_MAX]; time_t now = time(NULL); if (blackbox_file_prefix == NULL) { return; } switch (nsig) { case 0: case SIGTRAP: /* The graceful case - such as assertion failure or user request */ if (nsig == 0 && now == last) { /* Prevent over-dumping */ return; } snprintf(buffer, NAME_MAX, "%s.%d", blackbox_file_prefix, counter++); if (nsig == SIGTRAP) { pcmk__notice("Blackbox dump requested, please see %s for " "contents", buffer); } else if (cs) { syslog(LOG_NOTICE, "Problem detected at %s:%d (%s), please see %s for additional details", cs->function, cs->lineno, cs->filename, buffer); } else { pcmk__notice("Problem detected, please see %s for additional " "details", buffer); } last = now; qb_log_blackbox_write_to_file(buffer); /* Flush the existing contents * A size change would also work */ qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE); qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE); break; default: /* Do as little as possible, just try to get what we have out * We logged the filename when the blackbox was enabled */ crm_signal_handler(nsig, SIG_DFL); qb_log_blackbox_write_to_file((const char *)blackbox_file_prefix); qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE); raise(nsig); break; } } static const char * crm_quark_to_string(uint32_t tag) { const char *text = g_quark_to_string(tag); if (text) { return text; } return ""; } static void crm_log_filter_source(int source, const char *trace_files, const char *trace_fns, const char *trace_fmts, const char *trace_tags, const char *trace_blackbox, struct qb_log_callsite *cs) { if (qb_log_ctl(source, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) { return; } else if (cs->tags != crm_trace_nonlog && source == QB_LOG_BLACKBOX) { /* Blackbox gets everything if enabled */ qb_bit_set(cs->targets, source); } else if (source == blackbox_trigger && blackbox_trigger > 0) { /* Should this log message result in the blackbox being dumped */ if (cs->priority <= LOG_ERR) { qb_bit_set(cs->targets, source); } else if (trace_blackbox) { char *key = pcmk__assert_asprintf("%s:%d", cs->function, cs->lineno); if (strstr(trace_blackbox, key) != NULL) { qb_bit_set(cs->targets, source); } free(key); } } else if (source == QB_LOG_SYSLOG) { /* No tracing to syslog */ if (cs->priority <= crm_log_priority && cs->priority <= crm_log_level) { qb_bit_set(cs->targets, source); } /* Log file tracing options... */ } else if (cs->priority <= crm_log_level) { qb_bit_set(cs->targets, source); } else if (trace_files && strstr(trace_files, cs->filename) != NULL) { qb_bit_set(cs->targets, source); } else if (trace_fns && strstr(trace_fns, cs->function) != NULL) { qb_bit_set(cs->targets, source); } else if (trace_fmts && strstr(trace_fmts, cs->format) != NULL) { qb_bit_set(cs->targets, source); } else if (trace_tags && cs->tags != 0 && cs->tags != crm_trace_nonlog && g_quark_to_string(cs->tags) != NULL) { qb_bit_set(cs->targets, source); } } #ifndef HAVE_STRCHRNUL /* strchrnul() is a GNU extension. If not present, use our own definition. * The GNU version returns char*, but we only need it to be const char*. */ static const char * strchrnul(const char *s, int c) { while ((*s != c) && (*s != '\0')) { ++s; } return s; } #endif static void crm_log_filter(struct qb_log_callsite *cs) { int lpc = 0; static int need_init = 1; static const char *trace_fns = NULL; static const char *trace_tags = NULL; static const char *trace_fmts = NULL; static const char *trace_files = NULL; static const char *trace_blackbox = NULL; if (need_init) { need_init = 0; trace_fns = pcmk__env_option(PCMK__ENV_TRACE_FUNCTIONS); trace_fmts = pcmk__env_option(PCMK__ENV_TRACE_FORMATS); trace_tags = pcmk__env_option(PCMK__ENV_TRACE_TAGS); trace_files = pcmk__env_option(PCMK__ENV_TRACE_FILES); trace_blackbox = pcmk__env_option(PCMK__ENV_TRACE_BLACKBOX); if (trace_tags != NULL) { uint32_t tag; char token[500]; const char *offset = NULL; const char *next = trace_tags; do { offset = next; next = strchrnul(offset, ','); snprintf(token, sizeof(token), "%.*s", (int)(next - offset), offset); tag = g_quark_from_string(token); pcmk__info("Created GQuark %u from token '%s' in '%s'", tag, token, trace_tags); if (next[0] != 0) { next++; } } while (next != NULL && next[0] != 0); } } cs->targets = 0; /* Reset then find targets to enable */ for (lpc = QB_LOG_SYSLOG; lpc < QB_LOG_TARGET_MAX; lpc++) { crm_log_filter_source(lpc, trace_files, trace_fns, trace_fmts, trace_tags, trace_blackbox, cs); } } gboolean crm_is_callsite_active(struct qb_log_callsite *cs, uint8_t level, uint32_t tags) { gboolean refilter = FALSE; if (cs == NULL) { return FALSE; } if (cs->priority != level) { cs->priority = level; refilter = TRUE; } if (cs->tags != tags) { cs->tags = tags; refilter = TRUE; } if (refilter) { crm_log_filter(cs); } if (cs->targets == 0) { return FALSE; } return TRUE; } void crm_update_callsites(void) { static bool log = true; if (log) { log = false; pcmk__debug("Enabling callsites based on priority=%d, files=%s, " "functions=%s, formats=%s, tags=%s", crm_log_level, pcmk__s(pcmk__env_option(PCMK__ENV_TRACE_FILES), ""), pcmk__s(pcmk__env_option(PCMK__ENV_TRACE_FUNCTIONS), ""), pcmk__s(pcmk__env_option(PCMK__ENV_TRACE_FORMATS), ""), pcmk__s(pcmk__env_option(PCMK__ENV_TRACE_TAGS), "")); } qb_log_filter_fn_set(crm_log_filter); } static gboolean crm_tracing_enabled(void) { return (crm_log_level == LOG_TRACE) || (pcmk__env_option(PCMK__ENV_TRACE_FILES) != NULL) || (pcmk__env_option(PCMK__ENV_TRACE_FUNCTIONS) != NULL) || (pcmk__env_option(PCMK__ENV_TRACE_FORMATS) != NULL) || (pcmk__env_option(PCMK__ENV_TRACE_TAGS) != NULL); } static int crm_priority2int(const char *name) { struct syslog_names { const char *name; int priority; }; static struct syslog_names p_names[] = { {"emerg", LOG_EMERG}, {"alert", LOG_ALERT}, {"crit", LOG_CRIT}, {"error", LOG_ERR}, {"warning", LOG_WARNING}, {"notice", LOG_NOTICE}, {"info", LOG_INFO}, {"debug", LOG_DEBUG}, {NULL, -1} }; int lpc; for (lpc = 0; name != NULL && p_names[lpc].name != NULL; lpc++) { if (pcmk__str_eq(p_names[lpc].name, name, pcmk__str_none)) { return p_names[lpc].priority; } } return crm_log_priority; } /*! * \internal * \brief Set the identifier for the current process * * If the identifier crm_system_name is not already set, then it is set as follows: * - it is passed to the function via the "entity" parameter, or * - it is derived from the executable name * * The identifier can be used in logs, IPC, and more. * * This method also sets the PCMK_service environment variable. * * \param[in] entity If not NULL, will be assigned to the identifier * \param[in] argc The number of command line parameters * \param[in] argv The command line parameter values */ static void set_identity(const char *entity, int argc, char *const *argv) { if (crm_system_name != NULL) { return; // Already set, don't overwrite } if (entity != NULL) { crm_system_name = pcmk__str_copy(entity); } else if ((argc > 0) && (argv != NULL)) { char *mutable = strdup(argv[0]); char *modified = basename(mutable); if (strstr(modified, "lt-") == modified) { modified += 3; } crm_system_name = pcmk__str_copy(modified); free(mutable); } else { crm_system_name = pcmk__str_copy("Unknown"); } // Used by fencing.py.py (in fence-agents) pcmk__set_env_option(PCMK__ENV_SERVICE, crm_system_name, false); } void crm_log_preinit(const char *entity, int argc, char *const *argv) { /* Configure libqb logging with nothing turned on */ struct utsname res; int lpc = 0; int32_t qb_facility = 0; pid_t pid = getpid(); const char *nodename = "localhost"; static bool have_logging = false; GLogLevelFlags log_levels; if (have_logging) { return; } have_logging = true; pcmk__xml_init(); if (crm_trace_nonlog == 0) { crm_trace_nonlog = g_quark_from_static_string("Pacemaker non-logging tracepoint"); } umask(S_IWGRP | S_IWOTH | S_IROTH); /* Add a log handler for messages from our log domain at any log level. */ log_levels = G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION; pcmk__log_id = g_log_set_handler(G_LOG_DOMAIN, log_levels, crm_glib_handler, NULL); /* Add a log handler for messages from the GLib domains at any log level. */ pcmk__glib_log_id = g_log_set_handler("GLib", log_levels, crm_glib_handler, NULL); pcmk__gio_log_id = g_log_set_handler("GLib-GIO", log_levels, crm_glib_handler, NULL); pcmk__gmodule_log_id = g_log_set_handler("GModule", log_levels, crm_glib_handler, NULL); pcmk__gthread_log_id = g_log_set_handler("GThread", log_levels, crm_glib_handler, NULL); /* glib should not abort for any messages from the Pacemaker domain, but * other domains are still free to specify their own behavior. However, * note that G_LOG_LEVEL_ERROR is always fatal regardless of what we do * here. */ g_log_set_fatal_mask(G_LOG_DOMAIN, 0); /* Set crm_system_name, which is used as the logging name. It may also * be used for other purposes such as an IPC client name. */ set_identity(entity, argc, argv); qb_facility = qb_log_facility2int("local0"); qb_log_init(crm_system_name, qb_facility, LOG_ERR); crm_log_level = LOG_CRIT; /* Nuke any syslog activity until it's asked for */ qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE); #ifdef HAVE_qb_log_conf_QB_LOG_CONF_MAX_LINE_LEN // Shorter than default, generous for what we *should* send to syslog qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_MAX_LINE_LEN, 256); #endif if (uname(memset(&res, 0, sizeof(res))) == 0 && *res.nodename != '\0') { nodename = res.nodename; } /* Set format strings and disable threading * Pacemaker and threads do not mix well (due to the amount of forking) */ qb_log_tags_stringify_fn_set(crm_quark_to_string); for (lpc = QB_LOG_SYSLOG; lpc < QB_LOG_TARGET_MAX; lpc++) { qb_log_ctl(lpc, QB_LOG_CONF_THREADED, QB_FALSE); #ifdef HAVE_qb_log_conf_QB_LOG_CONF_ELLIPSIS // End truncated lines with '...' qb_log_ctl(lpc, QB_LOG_CONF_ELLIPSIS, QB_TRUE); #endif set_format_string(lpc, crm_system_name, pid, nodename); } #ifdef ENABLE_NLS /* Enable translations (experimental). Currently we only have a few * proof-of-concept translations for some option help. The goal would be to * offer translations for option help and man pages rather than logs or * documentation, to reduce the burden of maintaining them. */ // Load locale information for the local host from the environment setlocale(LC_ALL, ""); // Tell gettext where to find Pacemaker message catalogs pcmk__assert(bindtextdomain(PACKAGE, PCMK__LOCALE_DIR) != NULL); // Tell gettext to use the Pacemaker message catalogs pcmk__assert(textdomain(PACKAGE) != NULL); // Tell gettext that the translated strings are stored in UTF-8 bind_textdomain_codeset(PACKAGE, "UTF-8"); #endif } gboolean crm_log_init(const char *entity, uint8_t level, gboolean daemon, gboolean to_stderr, int argc, char **argv, gboolean quiet) { const char *syslog_priority = NULL; const char *facility = pcmk__env_option(PCMK__ENV_LOGFACILITY); const char *f_copy = facility; pcmk__is_daemon = daemon; crm_log_preinit(entity, argc, argv); if (level > LOG_TRACE) { level = LOG_TRACE; } if(level > crm_log_level) { crm_log_level = level; } /* Should we log to syslog */ if (facility == NULL) { if (pcmk__is_daemon) { facility = "daemon"; } else { facility = PCMK_VALUE_NONE; } pcmk__set_env_option(PCMK__ENV_LOGFACILITY, facility, true); } if (pcmk__str_eq(facility, PCMK_VALUE_NONE, pcmk__str_casei)) { quiet = TRUE; } else { qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_FACILITY, qb_log_facility2int(facility)); } if (pcmk__env_option_enabled(crm_system_name, PCMK__ENV_DEBUG)) { /* Override the default setting */ crm_log_level = LOG_DEBUG; } /* What lower threshold do we have for sending to syslog */ syslog_priority = pcmk__env_option(PCMK__ENV_LOGPRIORITY); if (syslog_priority) { crm_log_priority = crm_priority2int(syslog_priority); } qb_log_filter_ctl(QB_LOG_SYSLOG, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FILE, "*", crm_log_priority); // Log to syslog unless requested to be quiet if (!quiet) { qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_TRUE); } /* Should we log to stderr */ if (pcmk__env_option_enabled(crm_system_name, PCMK__ENV_STDERR)) { /* Override the default setting */ to_stderr = TRUE; } crm_enable_stderr(to_stderr); // Log to a file if we're a daemon or user asked for one { const char *logfile = pcmk__env_option(PCMK__ENV_LOGFILE); if (!pcmk__str_eq(PCMK_VALUE_NONE, logfile, pcmk__str_casei) && (pcmk__is_daemon || (logfile != NULL))) { // Daemons always get a log file, unless explicitly set to "none" pcmk__add_logfile(logfile); } } if (pcmk__is_daemon && pcmk__env_option_enabled(crm_system_name, PCMK__ENV_BLACKBOX)) { crm_enable_blackbox(0); } /* Summary */ crm_trace("Quiet: %d, facility %s", quiet, f_copy); pcmk__env_option(PCMK__ENV_LOGFILE); pcmk__env_option(PCMK__ENV_LOGFACILITY); crm_update_callsites(); /* Ok, now we can start logging... */ // Disable daemon request if user isn't root or Pacemaker daemon user if (pcmk__is_daemon) { const char *user = getenv("USER"); if (user != NULL && !pcmk__strcase_any_of(user, "root", CRM_DAEMON_USER, NULL)) { crm_trace("Not switching to corefile directory for %s", user); pcmk__is_daemon = false; } } if (pcmk__is_daemon) { int user = getuid(); struct passwd *pwent = getpwuid(user); if (pwent == NULL) { crm_perror(LOG_ERR, "Cannot get name for uid: %d", user); } else if (!pcmk__strcase_any_of(pwent->pw_name, "root", CRM_DAEMON_USER, NULL)) { crm_trace("Don't change active directory for regular user: %s", pwent->pw_name); } else if (chdir(CRM_CORE_DIR) < 0) { crm_perror(LOG_INFO, "Cannot change active directory to " CRM_CORE_DIR); } else { pcmk__info("Changed active directory to " CRM_CORE_DIR); } /* Original meanings from signal(7) * * Signal Value Action Comment * SIGTRAP 5 Core Trace/breakpoint trap * SIGUSR1 30,10,16 Term User-defined signal 1 * SIGUSR2 31,12,17 Term User-defined signal 2 * * Our usage is as similar as possible */ mainloop_add_signal(SIGUSR1, crm_enable_blackbox); mainloop_add_signal(SIGUSR2, crm_disable_blackbox); mainloop_add_signal(SIGTRAP, crm_trigger_blackbox); } else if (!quiet) { crm_log_args(argc, argv); } return TRUE; } /* returns the old value */ unsigned int set_crm_log_level(unsigned int level) { unsigned int old = crm_log_level; if (level > LOG_TRACE) { level = LOG_TRACE; } crm_log_level = level; crm_update_callsites(); crm_trace("New log level: %d", level); return old; } void crm_enable_stderr(int enable) { if (enable && qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) { qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_ENABLED, QB_TRUE); crm_update_callsites(); } else if (enable == FALSE) { qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_ENABLED, QB_FALSE); } } /*! * \brief Make logging more verbose * * If logging to stderr is not already enabled when this function is called, * enable it. Otherwise, increase the log level by 1. * * \param[in] argc Ignored * \param[in] argv Ignored */ void crm_bump_log_level(int argc, char **argv) { if (qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) { crm_enable_stderr(TRUE); } else { set_crm_log_level(crm_log_level + 1); } } unsigned int get_crm_log_level(void) { return crm_log_level; } /*! * \brief Log the command line (once) * * \param[in] Number of values in \p argv * \param[in] Command-line arguments (including command name) * * \note This function will only log once, even if called with different * arguments. */ void crm_log_args(int argc, char **argv) { static bool logged = false; gchar *arg_string = NULL; if ((argc == 0) || (argv == NULL) || logged) { return; } logged = true; arg_string = g_strjoinv(" ", argv); pcmk__notice("Invoked: %s", arg_string); g_free(arg_string); } void crm_log_output_fn(const char *file, const char *function, int line, int level, const char *prefix, const char *output) { const char *next = NULL; const char *offset = NULL; if (level == LOG_NEVER) { return; } if (output == NULL) { - if (level != LOG_STDOUT) { + if (level != PCMK__LOG_STDOUT) { level = LOG_TRACE; } output = "-- empty --"; } next = output; do { offset = next; next = strchrnul(offset, '\n'); do_crm_log_alias(level, file, function, line, "%s [ %.*s ]", prefix, (int)(next - offset), offset); if (next[0] != 0) { next++; } } while (next != NULL && next[0] != 0); } void pcmk__cli_init_logging(const char *name, unsigned int verbosity) { crm_log_init(name, LOG_ERR, FALSE, FALSE, 0, NULL, TRUE); for (int i = 0; i < verbosity; i++) { /* These arguments are ignored, so pass placeholders. */ crm_bump_log_level(0, NULL); } } /*! * \brief Log XML line-by-line in a formatted fashion * * \param[in] file File name to use for log filtering * \param[in] function Function name to use for log filtering * \param[in] line Line number to use for log filtering * \param[in] tags Logging tags to use for log filtering * \param[in] level Priority at which to log the messages * \param[in] text Prefix for each line * \param[in] xml XML to log * - * \note This does nothing when \p level is \p LOG_STDOUT. + * \note This does nothing when \p level is \c PCMK__LOG_STDOUT. * \note Do not call this function directly. It should be called only from the * \p do_crm_log_xml() macro. */ void pcmk_log_xml_as(const char *file, const char *function, uint32_t line, uint32_t tags, uint8_t level, const char *text, const xmlNode *xml) { if (xml == NULL) { do_crm_log(level, "%s%sNo data to dump as XML", pcmk__s(text, ""), pcmk__str_empty(text)? "" : " "); } else { if (logger_out == NULL) { CRM_CHECK(pcmk__log_output_new(&logger_out) == pcmk_rc_ok, return); } pcmk__output_set_log_level(logger_out, level); pcmk__output_set_log_filter(logger_out, file, function, line, tags); pcmk__xml_show(logger_out, text, xml, 1, pcmk__xml_fmt_pretty |pcmk__xml_fmt_open |pcmk__xml_fmt_children |pcmk__xml_fmt_close); pcmk__output_set_log_filter(logger_out, NULL, NULL, 0U, 0U); } } /*! * \internal * \brief Log XML changes line-by-line in a formatted fashion * * \param[in] file File name to use for log filtering * \param[in] function Function name to use for log filtering * \param[in] line Line number to use for log filtering * \param[in] tags Logging tags to use for log filtering * \param[in] level Priority at which to log the messages * \param[in] xml XML whose changes to log * - * \note This does nothing when \p level is \c LOG_STDOUT. + * \note This does nothing when \p level is \c PCMK__LOG_STDOUT. */ void pcmk__log_xml_changes_as(const char *file, const char *function, uint32_t line, uint32_t tags, uint8_t level, const xmlNode *xml) { if (xml == NULL) { do_crm_log(level, "No XML to dump"); return; } if (logger_out == NULL) { CRM_CHECK(pcmk__log_output_new(&logger_out) == pcmk_rc_ok, return); } pcmk__output_set_log_level(logger_out, level); pcmk__output_set_log_filter(logger_out, file, function, line, tags); pcmk__xml_show_changes(logger_out, xml); pcmk__output_set_log_filter(logger_out, NULL, NULL, 0U, 0U); } /*! * \internal * \brief Log an XML patchset line-by-line in a formatted fashion * * \param[in] file File name to use for log filtering * \param[in] function Function name to use for log filtering * \param[in] line Line number to use for log filtering * \param[in] tags Logging tags to use for log filtering * \param[in] level Priority at which to log the messages * \param[in] patchset XML patchset to log * - * \note This does nothing when \p level is \c LOG_STDOUT. + * \note This does nothing when \p level is \c PCMK__LOG_STDOUT. */ void pcmk__log_xml_patchset_as(const char *file, const char *function, uint32_t line, uint32_t tags, uint8_t level, const xmlNode *patchset) { if (patchset == NULL) { do_crm_log(level, "No patchset to dump"); return; } if (logger_out == NULL) { CRM_CHECK(pcmk__log_output_new(&logger_out) == pcmk_rc_ok, return); } pcmk__output_set_log_level(logger_out, level); pcmk__output_set_log_filter(logger_out, file, function, line, tags); logger_out->message(logger_out, "xml-patchset", patchset); pcmk__output_set_log_filter(logger_out, NULL, NULL, 0U, 0U); } /*! * \internal * \brief Free the logging library's internal log output object */ void pcmk__free_common_logger(void) { if (logger_out != NULL) { logger_out->finish(logger_out, CRM_EX_OK, true, NULL); pcmk__output_free(logger_out); logger_out = NULL; } } void pcmk__set_config_error_handler(pcmk__config_error_func error_handler, void *error_context) { pcmk__config_error_handler = error_handler; pcmk__config_error_context = error_context; } void pcmk__set_config_warning_handler(pcmk__config_warning_func warning_handler, void *warning_context) { pcmk__config_warning_handler = warning_handler; pcmk__config_warning_context = warning_context; } diff --git a/lib/common/mainloop.c b/lib/common/mainloop.c index 770e69ee88..95dc345105 100644 --- a/lib/common/mainloop.c +++ b/lib/common/mainloop.c @@ -1,1468 +1,1468 @@ /* * Copyright 2004-2025 the Pacemaker project contributors * * The version control history for this file may have further details. * * This source code is licensed under the GNU Lesser General Public License * version 2.1 or later (LGPLv2.1+) WITHOUT ANY WARRANTY. */ #include #include #include #include #include #include #include #include #include #include #include struct mainloop_child_s { pid_t pid; char *desc; unsigned timerid; gboolean timeout; void *privatedata; enum mainloop_child_flags flags; /* Called when a process dies */ void (*callback) (mainloop_child_t * p, pid_t pid, int core, int signo, int exitcode); }; struct trigger_s { GSource source; gboolean running; gboolean trigger; void *user_data; guint id; }; struct mainloop_timer_s { guint id; guint period_ms; bool repeat; char *name; GSourceFunc cb; void *userdata; }; static gboolean crm_trigger_prepare(GSource * source, gint * timeout) { crm_trigger_t *trig = (crm_trigger_t *) source; /* cluster-glue's FD and IPC related sources make use of * g_source_add_poll() but do not set a timeout in their prepare * functions * * This means mainloop's poll() will block until an event for one * of these sources occurs - any /other/ type of source, such as * this one or g_idle_*, that doesn't use g_source_add_poll() is * S-O-L and won't be processed until there is something fd-based * happens. * * Luckily the timeout we can set here affects all sources and * puts an upper limit on how long poll() can take. * * So unconditionally set a small-ish timeout, not too small that * we're in constant motion, which will act as an upper bound on * how long the signal handling might be delayed for. */ *timeout = 500; /* Timeout in ms */ return trig->trigger; } static gboolean crm_trigger_check(GSource * source) { crm_trigger_t *trig = (crm_trigger_t *) source; return trig->trigger; } /*! * \internal * \brief GSource dispatch function for crm_trigger_t * * \param[in] source crm_trigger_t being dispatched * \param[in] callback Callback passed at source creation * \param[in,out] userdata User data passed at source creation * * \return G_SOURCE_REMOVE to remove source, G_SOURCE_CONTINUE to keep it */ static gboolean crm_trigger_dispatch(GSource *source, GSourceFunc callback, gpointer userdata) { gboolean rc = G_SOURCE_CONTINUE; crm_trigger_t *trig = (crm_trigger_t *) source; if (trig->running) { /* Wait until the existing job is complete before starting the next one */ return G_SOURCE_CONTINUE; } trig->trigger = FALSE; if (callback) { int callback_rc = callback(trig->user_data); if (callback_rc < 0) { crm_trace("Trigger handler %p not yet complete", trig); trig->running = TRUE; } else if (callback_rc == 0) { rc = G_SOURCE_REMOVE; } } return rc; } static void crm_trigger_finalize(GSource * source) { crm_trace("Trigger %p destroyed", source); } static GSourceFuncs crm_trigger_funcs = { crm_trigger_prepare, crm_trigger_check, crm_trigger_dispatch, crm_trigger_finalize, }; static crm_trigger_t * mainloop_setup_trigger(GSource * source, int priority, int (*dispatch) (gpointer user_data), gpointer userdata) { crm_trigger_t *trigger = NULL; trigger = (crm_trigger_t *) source; trigger->id = 0; trigger->trigger = FALSE; trigger->user_data = userdata; if (dispatch) { g_source_set_callback(source, dispatch, trigger, NULL); } g_source_set_priority(source, priority); g_source_set_can_recurse(source, FALSE); trigger->id = g_source_attach(source, NULL); return trigger; } void mainloop_trigger_complete(crm_trigger_t * trig) { crm_trace("Trigger handler %p complete", trig); trig->running = FALSE; } /*! * \brief Create a trigger to be used as a mainloop source * * \param[in] priority Relative priority of source (lower number is higher priority) * \param[in] dispatch Trigger dispatch function (should return 0 to remove the * trigger from the mainloop, -1 if the trigger should be * kept but the job is still running and not complete, and * 1 if the trigger should be kept and the job is complete) * \param[in] userdata Pointer to pass to \p dispatch * * \return Newly allocated mainloop source for trigger */ crm_trigger_t * mainloop_add_trigger(int priority, int (*dispatch) (gpointer user_data), gpointer userdata) { GSource *source = NULL; pcmk__assert(sizeof(crm_trigger_t) > sizeof(GSource)); source = g_source_new(&crm_trigger_funcs, sizeof(crm_trigger_t)); return mainloop_setup_trigger(source, priority, dispatch, userdata); } void mainloop_set_trigger(crm_trigger_t * source) { if(source) { source->trigger = TRUE; } } gboolean mainloop_destroy_trigger(crm_trigger_t * source) { GSource *gs = NULL; if(source == NULL) { return TRUE; } gs = (GSource *)source; g_source_destroy(gs); /* Remove from mainloop, ref_count-- */ g_source_unref(gs); /* The caller no longer carries a reference to source * * At this point the source should be free'd, * unless we're currently processing said * source, in which case mainloop holds an * additional reference and it will be free'd * once our processing completes */ return TRUE; } // Define a custom glib source for signal handling // Data structure for custom glib source typedef struct signal_s { crm_trigger_t trigger; // trigger that invoked source (must be first) void (*handler) (int sig); // signal handler int signal; // signal that was received } crm_signal_t; // Table to associate signal handlers with signal numbers static crm_signal_t *crm_signals[NSIG]; /*! * \internal * \brief Dispatch an event from custom glib source for signals * * Given an signal event, clear the event trigger and call any registered * signal handler. * * \param[in] source glib source that triggered this dispatch * \param[in] callback (ignored) * \param[in] userdata (ignored) */ static gboolean crm_signal_dispatch(GSource *source, GSourceFunc callback, gpointer userdata) { crm_signal_t *sig = (crm_signal_t *) source; if(sig->signal != SIGCHLD) { pcmk__notice("Caught '%s' signal " QB_XS " %d (%s handler)", strsignal(sig->signal), sig->signal, ((sig->handler != NULL)? "invoking" : "no")); } sig->trigger.trigger = FALSE; if (sig->handler) { sig->handler(sig->signal); } return TRUE; } /*! * \internal * \brief Handle a signal by setting a trigger for signal source * * \param[in] sig Signal number that was received * * \note This is the true signal handler for the mainloop signal source, and * must be async-safe. */ static void mainloop_signal_handler(int sig) { if (sig > 0 && sig < NSIG && crm_signals[sig] != NULL) { mainloop_set_trigger((crm_trigger_t *) crm_signals[sig]); } } // Functions implementing our custom glib source for signal handling static GSourceFuncs crm_signal_funcs = { crm_trigger_prepare, crm_trigger_check, crm_signal_dispatch, crm_trigger_finalize, }; /*! * \internal * \brief Set a true signal handler * * signal()-like interface to sigaction() * * \param[in] sig Signal number to register handler for * \param[in] dispatch Signal handler * * \return The previous value of the signal handler, or SIG_ERR on error * \note The dispatch function must be async-safe. */ sighandler_t crm_signal_handler(int sig, sighandler_t dispatch) { sigset_t mask; struct sigaction sa; struct sigaction old; if (sigemptyset(&mask) < 0) { pcmk__err("Could not set handler for signal %d: %s", sig, pcmk_rc_str(errno)); return SIG_ERR; } memset(&sa, 0, sizeof(struct sigaction)); sa.sa_handler = dispatch; sa.sa_flags = SA_RESTART; sa.sa_mask = mask; if (sigaction(sig, &sa, &old) < 0) { pcmk__err("Could not set handler for signal %d: %s", sig, pcmk_rc_str(errno)); return SIG_ERR; } return old.sa_handler; } static void mainloop_destroy_signal_entry(int sig) { crm_signal_t *tmp = crm_signals[sig]; if (tmp != NULL) { crm_signals[sig] = NULL; crm_trace("Unregistering mainloop handler for signal %d", sig); mainloop_destroy_trigger((crm_trigger_t *) tmp); } } /*! * \internal * \brief Add a signal handler to a mainloop * * \param[in] sig Signal number to handle * \param[in] dispatch Signal handler function * * \note The true signal handler merely sets a mainloop trigger to call this * dispatch function via the mainloop. Therefore, the dispatch function * does not need to be async-safe. */ gboolean mainloop_add_signal(int sig, void (*dispatch) (int sig)) { GSource *source = NULL; int priority = G_PRIORITY_HIGH - 1; if (sig == SIGTERM) { /* TERM is higher priority than other signals, * signals are higher priority than other ipc. * Yes, minus: smaller is "higher" */ priority--; } if (sig >= NSIG || sig < 0) { pcmk__err("Signal %d is out of range", sig); return FALSE; } else if (crm_signals[sig] != NULL && crm_signals[sig]->handler == dispatch) { crm_trace("Signal handler for %d is already installed", sig); return TRUE; } else if (crm_signals[sig] != NULL) { pcmk__err("Different signal handler for %d is already installed", sig); return FALSE; } pcmk__assert(sizeof(crm_signal_t) > sizeof(GSource)); source = g_source_new(&crm_signal_funcs, sizeof(crm_signal_t)); crm_signals[sig] = (crm_signal_t *) mainloop_setup_trigger(source, priority, NULL, NULL); pcmk__assert(crm_signals[sig] != NULL); crm_signals[sig]->handler = dispatch; crm_signals[sig]->signal = sig; if (crm_signal_handler(sig, mainloop_signal_handler) == SIG_ERR) { mainloop_destroy_signal_entry(sig); return FALSE; } return TRUE; } gboolean mainloop_destroy_signal(int sig) { if (sig >= NSIG || sig < 0) { pcmk__err("Signal %d is out of range", sig); return FALSE; } else if (crm_signal_handler(sig, NULL) == SIG_ERR) { crm_perror(LOG_ERR, "Could not uninstall signal handler for signal %d", sig); return FALSE; } else if (crm_signals[sig] == NULL) { return TRUE; } mainloop_destroy_signal_entry(sig); return TRUE; } static qb_array_t *gio_map = NULL; void mainloop_cleanup(void) { if (gio_map != NULL) { qb_array_free(gio_map); gio_map = NULL; } for (int sig = 0; sig < NSIG; ++sig) { mainloop_destroy_signal_entry(sig); } } /* * libqb... */ struct gio_to_qb_poll { int32_t is_used; guint source; int32_t events; void *data; qb_ipcs_dispatch_fn_t fn; enum qb_loop_priority p; }; static gboolean gio_read_socket(GIOChannel * gio, GIOCondition condition, gpointer data) { struct gio_to_qb_poll *adaptor = (struct gio_to_qb_poll *)data; gint fd = g_io_channel_unix_get_fd(gio); crm_trace("%p.%d %d", data, fd, condition); /* if this assert get's hit, then there is a race condition between * when we destroy a fd and when mainloop actually gives it up */ pcmk__assert(adaptor->is_used > 0); return (adaptor->fn(fd, condition, adaptor->data) == 0); } static void gio_poll_destroy(gpointer data) { struct gio_to_qb_poll *adaptor = (struct gio_to_qb_poll *)data; adaptor->is_used--; pcmk__assert(adaptor->is_used >= 0); if (adaptor->is_used == 0) { crm_trace("Marking adaptor %p unused", adaptor); adaptor->source = 0; } } /*! * \internal * \brief Convert libqb's poll priority into GLib's one * * \param[in] prio libqb's poll priority (#QB_LOOP_MED assumed as fallback) * * \return best matching GLib's priority */ static gint conv_prio_libqb2glib(enum qb_loop_priority prio) { switch (prio) { case QB_LOOP_LOW: return G_PRIORITY_LOW; case QB_LOOP_HIGH: return G_PRIORITY_HIGH; default: return G_PRIORITY_DEFAULT; // QB_LOOP_MED } } /*! * \internal * \brief Convert libqb's poll priority to rate limiting spec * * \param[in] prio libqb's poll priority (#QB_LOOP_MED assumed as fallback) * * \return best matching rate limiting spec * \note This is the inverse of libqb's qb_ipcs_request_rate_limit(). */ static enum qb_ipcs_rate_limit conv_libqb_prio2ratelimit(enum qb_loop_priority prio) { switch (prio) { case QB_LOOP_LOW: return QB_IPCS_RATE_SLOW; case QB_LOOP_HIGH: return QB_IPCS_RATE_FAST; default: return QB_IPCS_RATE_NORMAL; // QB_LOOP_MED } } static int32_t gio_poll_dispatch_update(enum qb_loop_priority p, int32_t fd, int32_t evts, void *data, qb_ipcs_dispatch_fn_t fn, int32_t add) { struct gio_to_qb_poll *adaptor; GIOChannel *channel; int32_t res = 0; res = qb_array_index(gio_map, fd, (void **)&adaptor); if (res < 0) { pcmk__err("Array lookup failed for fd=%d: %d", fd, res); return res; } crm_trace("Adding fd=%d to mainloop as adaptor %p", fd, adaptor); if (add && adaptor->source) { pcmk__err("Adaptor for descriptor %d is still in-use", fd); return -EEXIST; } if (!add && !adaptor->is_used) { pcmk__err("Adaptor for descriptor %d is not in-use", fd); return -ENOENT; } /* channel is created with ref_count = 1 */ channel = g_io_channel_unix_new(fd); if (!channel) { pcmk__err("No memory left to add fd=%d", fd); return -ENOMEM; } if (adaptor->source) { g_source_remove(adaptor->source); adaptor->source = 0; } /* Because unlike the poll() API, glib doesn't tell us about HUPs by default */ evts |= (G_IO_HUP | G_IO_NVAL | G_IO_ERR); adaptor->fn = fn; adaptor->events = evts; adaptor->data = data; adaptor->p = p; adaptor->is_used++; adaptor->source = g_io_add_watch_full(channel, conv_prio_libqb2glib(p), evts, gio_read_socket, adaptor, gio_poll_destroy); /* Now that mainloop now holds a reference to channel, * thanks to g_io_add_watch_full(), drop ours from g_io_channel_unix_new(). * * This means that channel will be free'd by: * g_main_context_dispatch() * -> g_source_destroy_internal() * -> g_source_callback_unref() * shortly after gio_poll_destroy() completes */ g_io_channel_unref(channel); crm_trace("Added to mainloop with gsource id=%d", adaptor->source); if (adaptor->source > 0) { return 0; } return -EINVAL; } static int32_t gio_poll_dispatch_add(enum qb_loop_priority p, int32_t fd, int32_t evts, void *data, qb_ipcs_dispatch_fn_t fn) { return gio_poll_dispatch_update(p, fd, evts, data, fn, QB_TRUE); } static int32_t gio_poll_dispatch_mod(enum qb_loop_priority p, int32_t fd, int32_t evts, void *data, qb_ipcs_dispatch_fn_t fn) { return gio_poll_dispatch_update(p, fd, evts, data, fn, QB_FALSE); } static int32_t gio_poll_dispatch_del(int32_t fd) { struct gio_to_qb_poll *adaptor; crm_trace("Looking for fd=%d", fd); if (qb_array_index(gio_map, fd, (void **)&adaptor) == 0) { if (adaptor->source) { g_source_remove(adaptor->source); adaptor->source = 0; } } return 0; } struct qb_ipcs_poll_handlers gio_poll_funcs = { .job_add = NULL, .dispatch_add = gio_poll_dispatch_add, .dispatch_mod = gio_poll_dispatch_mod, .dispatch_del = gio_poll_dispatch_del, }; static enum qb_ipc_type pick_ipc_type(enum qb_ipc_type requested) { const char *env = pcmk__env_option(PCMK__ENV_IPC_TYPE); if (env && strcmp("shared-mem", env) == 0) { return QB_IPC_SHM; } else if (env && strcmp("socket", env) == 0) { return QB_IPC_SOCKET; } else if (env && strcmp("posix", env) == 0) { return QB_IPC_POSIX_MQ; } else if (env && strcmp("sysv", env) == 0) { return QB_IPC_SYSV_MQ; } else if (requested == QB_IPC_NATIVE) { /* We prefer shared memory because the server never blocks on * send. If part of a message fits into the socket, libqb * needs to block until the remainder can be sent also. * Otherwise the client will wait forever for the remaining * bytes. */ return QB_IPC_SHM; } return requested; } qb_ipcs_service_t * mainloop_add_ipc_server(const char *name, enum qb_ipc_type type, struct qb_ipcs_service_handlers *callbacks) { return mainloop_add_ipc_server_with_prio(name, type, callbacks, QB_LOOP_MED); } qb_ipcs_service_t * mainloop_add_ipc_server_with_prio(const char *name, enum qb_ipc_type type, struct qb_ipcs_service_handlers *callbacks, enum qb_loop_priority prio) { int rc = 0; qb_ipcs_service_t *server = NULL; if (gio_map == NULL) { gio_map = qb_array_create_2(64, sizeof(struct gio_to_qb_poll), 1); } server = qb_ipcs_create(name, 0, pick_ipc_type(type), callbacks); if (server == NULL) { pcmk__err("Could not create %s IPC server: %s (%d)", name, pcmk_rc_str(errno), errno); return NULL; } if (prio != QB_LOOP_MED) { qb_ipcs_request_rate_limit(server, conv_libqb_prio2ratelimit(prio)); } // All clients should use at least PCMK_ipc_buffer as their buffer size qb_ipcs_enforce_buffer_size(server, crm_ipc_default_buffer_size()); qb_ipcs_poll_handlers_set(server, &gio_poll_funcs); rc = qb_ipcs_run(server); if (rc < 0) { pcmk__err("Could not start %s IPC server: %s (%d)", name, pcmk_strerror(rc), rc); return NULL; // qb_ipcs_run() destroys server on failure } return server; } void mainloop_del_ipc_server(qb_ipcs_service_t * server) { if (server) { qb_ipcs_destroy(server); } } struct mainloop_io_s { char *name; void *userdata; int fd; guint source; crm_ipc_t *ipc; GIOChannel *channel; int (*dispatch_fn_ipc) (const char *buffer, ssize_t length, gpointer userdata); int (*dispatch_fn_io) (gpointer userdata); void (*destroy_fn) (gpointer userdata); }; /*! * \internal * \brief I/O watch callback function (GIOFunc) * * \param[in] gio I/O channel being watched * \param[in] condition I/O condition satisfied * \param[in] data User data passed when source was created * * \return G_SOURCE_REMOVE to remove source, G_SOURCE_CONTINUE to keep it */ static gboolean mainloop_gio_callback(GIOChannel *gio, GIOCondition condition, gpointer data) { gboolean rc = G_SOURCE_CONTINUE; mainloop_io_t *client = data; pcmk__assert(client->fd == g_io_channel_unix_get_fd(gio)); if (condition & G_IO_IN) { if (client->ipc) { long read_rc = 0L; int max = 10; do { read_rc = crm_ipc_read(client->ipc); if (read_rc <= 0) { crm_trace("Could not read IPC message from %s: %s (%ld)", client->name, pcmk_strerror(read_rc), read_rc); } else if (client->dispatch_fn_ipc) { const char *buffer = crm_ipc_buffer(client->ipc); crm_trace("New %ld-byte IPC message from %s " "after I/O condition %d", read_rc, client->name, (int) condition); if (client->dispatch_fn_ipc(buffer, read_rc, client->userdata) < 0) { crm_trace("Connection to %s no longer required", client->name); rc = G_SOURCE_REMOVE; } } } while ((rc == G_SOURCE_CONTINUE) && (read_rc > 0) && --max > 0); } else { crm_trace("New I/O event for %s after I/O condition %d", client->name, (int) condition); if (client->dispatch_fn_io) { if (client->dispatch_fn_io(client->userdata) < 0) { crm_trace("Connection to %s no longer required", client->name); rc = G_SOURCE_REMOVE; } } } } if (client->ipc && !crm_ipc_connected(client->ipc)) { pcmk__err("Connection to %s closed " QB_XS " client=%p condition=%d", client->name, client, condition); rc = G_SOURCE_REMOVE; } else if (condition & (G_IO_HUP | G_IO_NVAL | G_IO_ERR)) { crm_trace("The connection %s[%p] has been closed (I/O condition=%d)", client->name, client, condition); rc = G_SOURCE_REMOVE; } else if ((condition & G_IO_IN) == 0) { /* #define GLIB_SYSDEF_POLLIN =1 #define GLIB_SYSDEF_POLLPRI =2 #define GLIB_SYSDEF_POLLOUT =4 #define GLIB_SYSDEF_POLLERR =8 #define GLIB_SYSDEF_POLLHUP =16 #define GLIB_SYSDEF_POLLNVAL =32 typedef enum { G_IO_IN GLIB_SYSDEF_POLLIN, G_IO_OUT GLIB_SYSDEF_POLLOUT, G_IO_PRI GLIB_SYSDEF_POLLPRI, G_IO_ERR GLIB_SYSDEF_POLLERR, G_IO_HUP GLIB_SYSDEF_POLLHUP, G_IO_NVAL GLIB_SYSDEF_POLLNVAL } GIOCondition; A bitwise combination representing a condition to watch for on an event source. G_IO_IN There is data to read. G_IO_OUT Data can be written (without blocking). G_IO_PRI There is urgent data to read. G_IO_ERR Error condition. G_IO_HUP Hung up (the connection has been broken, usually for pipes and sockets). G_IO_NVAL Invalid request. The file descriptor is not open. */ pcmk__err("Strange condition: %d", condition); } /* G_SOURCE_REMOVE results in mainloop_gio_destroy() being called * just before the source is removed from mainloop */ return rc; } static void mainloop_gio_destroy(gpointer c) { mainloop_io_t *client = c; char *c_name = strdup(client->name); /* client->source is valid but about to be destroyed (ref_count == 0) in gmain.c * client->channel will still have ref_count > 0... should be == 1 */ crm_trace("Destroying client %s[%p]", c_name, c); if (client->ipc) { crm_ipc_close(client->ipc); } if (client->destroy_fn) { void (*destroy_fn) (gpointer userdata) = client->destroy_fn; client->destroy_fn = NULL; destroy_fn(client->userdata); } if (client->ipc) { crm_ipc_t *ipc = client->ipc; client->ipc = NULL; crm_ipc_destroy(ipc); } crm_trace("Destroyed client %s[%p]", c_name, c); free(client->name); client->name = NULL; free(client); free(c_name); } /*! * \brief Connect to IPC and add it as a main loop source * * \param[in,out] ipc IPC connection to add * \param[in] priority Event source priority to use for connection * \param[in] userdata Data to register with callbacks * \param[in] callbacks Dispatch and destroy callbacks for connection * \param[out] source Newly allocated event source * * \return Standard Pacemaker return code * * \note On failure, the caller is still responsible for ipc. On success, the * caller should call mainloop_del_ipc_client() when source is no longer * needed, which will lead to the disconnection of the IPC later in the * main loop if it is connected. However the IPC disconnects, * mainloop_gio_destroy() will free ipc and source after calling the * destroy callback. */ int pcmk__add_mainloop_ipc(crm_ipc_t *ipc, int priority, void *userdata, const struct ipc_client_callbacks *callbacks, mainloop_io_t **source) { int rc = pcmk_rc_ok; int fd = -1; const char *ipc_name = NULL; CRM_CHECK((ipc != NULL) && (callbacks != NULL), return EINVAL); ipc_name = pcmk__s(crm_ipc_name(ipc), "Pacemaker"); rc = pcmk__connect_generic_ipc(ipc); if (rc != pcmk_rc_ok) { pcmk__debug("Connection to %s failed: %s", ipc_name, pcmk_rc_str(rc)); return rc; } rc = pcmk__ipc_fd(ipc, &fd); if (rc != pcmk_rc_ok) { pcmk__debug("Could not obtain file descriptor for %s IPC: %s", ipc_name, pcmk_rc_str(rc)); crm_ipc_close(ipc); return rc; } *source = mainloop_add_fd(ipc_name, priority, fd, userdata, NULL); if (*source == NULL) { rc = errno; crm_ipc_close(ipc); return rc; } (*source)->ipc = ipc; (*source)->destroy_fn = callbacks->destroy; (*source)->dispatch_fn_ipc = callbacks->dispatch; return pcmk_rc_ok; } /*! * \brief Get period for mainloop timer * * \param[in] timer Timer * * \return Period in ms */ guint pcmk__mainloop_timer_get_period(const mainloop_timer_t *timer) { if (timer) { return timer->period_ms; } return 0; } mainloop_io_t * mainloop_add_ipc_client(const char *name, int priority, size_t max_size, void *userdata, struct ipc_client_callbacks *callbacks) { crm_ipc_t *ipc = crm_ipc_new(name, max_size); mainloop_io_t *source = NULL; int rc = pcmk__add_mainloop_ipc(ipc, priority, userdata, callbacks, &source); if (rc != pcmk_rc_ok) { - if (crm_log_level == LOG_STDOUT) { + if (crm_log_level == PCMK__LOG_STDOUT) { fprintf(stderr, "Connection to %s failed: %s", name, pcmk_rc_str(rc)); } crm_ipc_destroy(ipc); if (rc > 0) { errno = rc; } else { errno = ENOTCONN; } return NULL; } return source; } void mainloop_del_ipc_client(mainloop_io_t * client) { mainloop_del_fd(client); } crm_ipc_t * mainloop_get_ipc_client(mainloop_io_t * client) { if (client) { return client->ipc; } return NULL; } mainloop_io_t * mainloop_add_fd(const char *name, int priority, int fd, void *userdata, struct mainloop_fd_callbacks * callbacks) { mainloop_io_t *client = NULL; if (fd >= 0) { client = calloc(1, sizeof(mainloop_io_t)); if (client == NULL) { return NULL; } client->name = strdup(name); client->userdata = userdata; if (callbacks) { client->destroy_fn = callbacks->destroy; client->dispatch_fn_io = callbacks->dispatch; } client->fd = fd; client->channel = g_io_channel_unix_new(fd); client->source = g_io_add_watch_full(client->channel, priority, (G_IO_IN | G_IO_HUP | G_IO_NVAL | G_IO_ERR), mainloop_gio_callback, client, mainloop_gio_destroy); /* Now that mainloop now holds a reference to channel, * thanks to g_io_add_watch_full(), drop ours from g_io_channel_unix_new(). * * This means that channel will be free'd by: * g_main_context_dispatch() or g_source_remove() * -> g_source_destroy_internal() * -> g_source_callback_unref() * shortly after mainloop_gio_destroy() completes */ g_io_channel_unref(client->channel); crm_trace("Added connection %d for %s[%p].%d", client->source, client->name, client, fd); } else { errno = EINVAL; } return client; } void mainloop_del_fd(mainloop_io_t * client) { if (client != NULL) { crm_trace("Removing client %s[%p]", client->name, client); if (client->source) { /* Results in mainloop_gio_destroy() being called just * before the source is removed from mainloop */ g_source_remove(client->source); } } } static GList *child_list = NULL; pid_t mainloop_child_pid(mainloop_child_t * child) { return child->pid; } const char * mainloop_child_name(mainloop_child_t * child) { return child->desc; } int mainloop_child_timeout(mainloop_child_t * child) { return child->timeout; } void * mainloop_child_userdata(mainloop_child_t * child) { return child->privatedata; } void mainloop_clear_child_userdata(mainloop_child_t * child) { child->privatedata = NULL; } /* good function name */ static void child_free(mainloop_child_t *child) { if (child->timerid != 0) { crm_trace("Removing timer %d", child->timerid); g_source_remove(child->timerid); child->timerid = 0; } free(child->desc); free(child); } /* terrible function name */ static int child_kill_helper(mainloop_child_t *child) { int rc; if (child->flags & mainloop_leave_pid_group) { pcmk__debug("Kill pid %lld only. leave group intact", (long long) child->pid); rc = kill(child->pid, SIGKILL); } else { pcmk__debug("Kill pid %lld's group", (long long) child->pid); rc = kill(-child->pid, SIGKILL); } if (rc < 0) { if (errno != ESRCH) { crm_perror(LOG_ERR, "kill(%d, KILL) failed", child->pid); } return -errno; } return 0; } static gboolean child_timeout_callback(gpointer p) { mainloop_child_t *child = p; int rc = 0; child->timerid = 0; if (child->timeout) { pcmk__warn("%s process (PID %lld) will not die!", child->desc, (long long) child->pid); return FALSE; } rc = child_kill_helper(child); if (rc == -ESRCH) { /* Nothing left to do. pid doesn't exist */ return FALSE; } child->timeout = TRUE; pcmk__debug("%s process (PID %lld) timed out", child->desc, (long long) child->pid); child->timerid = pcmk__create_timer(5000, child_timeout_callback, child); return FALSE; } static bool child_waitpid(mainloop_child_t *child, int flags) { int rc = 0; int core = 0; int signo = 0; int status = 0; int exitcode = 0; bool callback_needed = true; rc = waitpid(child->pid, &status, flags); if (rc == 0) { // WNOHANG in flags, and child status is not available crm_trace("Child process %d (%s) still active", child->pid, child->desc); callback_needed = false; } else if (rc != child->pid) { /* According to POSIX, possible conditions: * - child->pid was non-positive (process group or any child), * and rc is specific child * - errno ECHILD (pid does not exist or is not child) * - errno EINVAL (invalid flags) * - errno EINTR (caller interrupted by signal) * * @TODO Handle these cases more specifically. */ signo = SIGCHLD; exitcode = 1; pcmk__notice("Wait for child process %d (%s) interrupted: %s", child->pid, child->desc, pcmk_rc_str(errno)); } else if (WIFEXITED(status)) { exitcode = WEXITSTATUS(status); crm_trace("Child process %d (%s) exited with status %d", child->pid, child->desc, exitcode); } else if (WIFSIGNALED(status)) { signo = WTERMSIG(status); crm_trace("Child process %d (%s) exited with signal %d (%s)", child->pid, child->desc, signo, strsignal(signo)); #ifdef WCOREDUMP // AIX, SunOS, maybe others } else if (WCOREDUMP(status)) { core = 1; pcmk__err("Child process %d (%s) dumped core", child->pid, child->desc); #endif } else { // flags must contain WUNTRACED and/or WCONTINUED to reach this crm_trace("Child process %d (%s) stopped or continued", child->pid, child->desc); callback_needed = false; } if (callback_needed && child->callback) { child->callback(child, child->pid, core, signo, exitcode); } return callback_needed; } static void child_death_dispatch(int signal) { for (GList *iter = child_list; iter; ) { GList *saved = iter; mainloop_child_t *child = iter->data; iter = iter->next; if (child_waitpid(child, WNOHANG)) { crm_trace("Removing completed process %d from child list", child->pid); child_list = g_list_remove_link(child_list, saved); g_list_free(saved); child_free(child); } } } static gboolean child_signal_init(gpointer p) { crm_trace("Installed SIGCHLD handler"); /* Do NOT use g_child_watch_add() and friends, they rely on pthreads */ mainloop_add_signal(SIGCHLD, child_death_dispatch); /* In case they terminated before the signal handler was installed */ child_death_dispatch(SIGCHLD); return FALSE; } gboolean mainloop_child_kill(pid_t pid) { GList *iter; mainloop_child_t *child = NULL; mainloop_child_t *match = NULL; /* It is impossible to block SIGKILL, this allows us to * call waitpid without WNOHANG flag.*/ int waitflags = 0, rc = 0; for (iter = child_list; iter != NULL && match == NULL; iter = iter->next) { child = iter->data; if (pid == child->pid) { match = child; } } if (match == NULL) { return FALSE; } rc = child_kill_helper(match); if(rc == -ESRCH) { /* It's gone, but hasn't shown up in waitpid() yet. Wait until we get * SIGCHLD and let handler clean it up as normal (so we get the correct * return code/status). The blocking alternative would be to call * child_waitpid(match, 0). */ crm_trace("Waiting for signal that child process %d completed", match->pid); return TRUE; } else if(rc != 0) { /* If KILL for some other reason set the WNOHANG flag since we * can't be certain what happened. */ waitflags = WNOHANG; } if (!child_waitpid(match, waitflags)) { /* not much we can do if this occurs */ return FALSE; } child_list = g_list_remove(child_list, match); child_free(match); return TRUE; } /* Create/Log a new tracked process * To track a process group, use -pid * * @TODO Using a non-positive pid (i.e. any child, or process group) would * likely not be useful since we will free the child after the first * completed process. */ void mainloop_child_add_with_flags(pid_t pid, int timeout, const char *desc, void *privatedata, enum mainloop_child_flags flags, void (*callback) (mainloop_child_t * p, pid_t pid, int core, int signo, int exitcode)) { static bool need_init = TRUE; mainloop_child_t *child = pcmk__assert_alloc(1, sizeof(mainloop_child_t)); child->pid = pid; child->timerid = 0; child->timeout = FALSE; child->privatedata = privatedata; child->callback = callback; child->flags = flags; child->desc = pcmk__str_copy(desc); if (timeout) { child->timerid = pcmk__create_timer(timeout, child_timeout_callback, child); } child_list = g_list_append(child_list, child); if(need_init) { need_init = FALSE; /* SIGCHLD processing has to be invoked from mainloop. * We do not want it to be possible to both add a child pid * to mainloop, and have the pid's exit callback invoked within * the same callstack. */ pcmk__create_timer(1, child_signal_init, NULL); } } void mainloop_child_add(pid_t pid, int timeout, const char *desc, void *privatedata, void (*callback) (mainloop_child_t * p, pid_t pid, int core, int signo, int exitcode)) { mainloop_child_add_with_flags(pid, timeout, desc, privatedata, 0, callback); } static gboolean mainloop_timer_cb(gpointer user_data) { int id = 0; bool repeat = FALSE; struct mainloop_timer_s *t = user_data; pcmk__assert(t != NULL); id = t->id; t->id = 0; /* Ensure it's unset during callbacks so that * mainloop_timer_running() works as expected */ if(t->cb) { crm_trace("Invoking callbacks for timer %s", t->name); repeat = t->repeat; if(t->cb(t->userdata) == FALSE) { crm_trace("Timer %s complete", t->name); repeat = FALSE; } } if(repeat) { /* Restore if repeating */ t->id = id; } return repeat; } bool mainloop_timer_running(mainloop_timer_t *t) { if(t && t->id != 0) { return TRUE; } return FALSE; } void mainloop_timer_start(mainloop_timer_t *t) { mainloop_timer_stop(t); if(t && t->period_ms > 0) { crm_trace("Starting timer %s", t->name); t->id = pcmk__create_timer(t->period_ms, mainloop_timer_cb, t); } } void mainloop_timer_stop(mainloop_timer_t *t) { if(t && t->id != 0) { crm_trace("Stopping timer %s", t->name); g_source_remove(t->id); t->id = 0; } } guint mainloop_timer_set_period(mainloop_timer_t *t, guint period_ms) { guint last = 0; if(t) { last = t->period_ms; t->period_ms = period_ms; } if(t && t->id != 0 && last != t->period_ms) { mainloop_timer_start(t); } return last; } mainloop_timer_t * mainloop_timer_add(const char *name, guint period_ms, bool repeat, GSourceFunc cb, void *userdata) { mainloop_timer_t *t = pcmk__assert_alloc(1, sizeof(mainloop_timer_t)); if (name != NULL) { t->name = pcmk__assert_asprintf("%s-%u-%d", name, period_ms, repeat); } else { t->name = pcmk__assert_asprintf("%p-%u-%d", t, period_ms, repeat); } t->id = 0; t->period_ms = period_ms; t->repeat = repeat; t->cb = cb; t->userdata = userdata; crm_trace("Created timer %s with %p %p", t->name, userdata, t->userdata); return t; } void mainloop_timer_del(mainloop_timer_t *t) { if(t) { crm_trace("Destroying timer %s", t->name); mainloop_timer_stop(t); free(t->name); free(t); } } /* * Helpers to make sure certain events aren't lost at shutdown */ static gboolean drain_timeout_cb(gpointer user_data) { bool *timeout_popped = (bool*) user_data; *timeout_popped = TRUE; return FALSE; } /*! * \brief Drain some remaining main loop events then quit it * * \param[in,out] mloop Main loop to drain and quit * \param[in] n Drain up to this many pending events */ void pcmk_quit_main_loop(GMainLoop *mloop, unsigned int n) { if ((mloop != NULL) && g_main_loop_is_running(mloop)) { GMainContext *ctx = g_main_loop_get_context(mloop); /* Drain up to n events in case some memory clean-up is pending * (helpful to reduce noise in valgrind output). */ for (int i = 0; (i < n) && g_main_context_pending(ctx); ++i) { g_main_context_dispatch(ctx); } g_main_loop_quit(mloop); } } /*! * \brief Process main loop events while a certain condition is met * * \param[in,out] mloop Main loop to process * \param[in] timer_ms Don't process longer than this amount of time * \param[in] check Function that returns true if events should be * processed * * \note This function is intended to be called at shutdown if certain important * events should not be missed. The caller would likely quit the main loop * or exit after calling this function. The check() function will be * passed the remaining timeout in milliseconds. */ void pcmk_drain_main_loop(GMainLoop *mloop, guint timer_ms, bool (*check)(guint)) { bool timeout_popped = FALSE; guint timer = 0; GMainContext *ctx = NULL; CRM_CHECK(mloop && check, return); ctx = g_main_loop_get_context(mloop); if (ctx) { time_t start_time = time(NULL); timer = pcmk__create_timer(timer_ms, drain_timeout_cb, &timeout_popped); while (!timeout_popped && check(timer_ms - (time(NULL) - start_time) * 1000)) { g_main_context_iteration(ctx, TRUE); } } if (!timeout_popped && (timer > 0)) { g_source_remove(timer); } }