/*****************************************************************************\ * log.c - slurm logging facilities ***************************************************************************** * Copyright (C) 2002-2007 The Regents of the University of California. * Copyright (C) 2008-2010 Lawrence Livermore National Security. * Produced at Lawrence Livermore National Laboratory (cf, DISCLAIMER). * Written by Mark Grondona * CODE-OCEC-09-009. All rights reserved. * * Much of this code was derived or adapted from the log.c component of * openssh which contains the following notices: ***************************************************************************** * Author: Tatu Ylonen * Copyright (c) 1995 Tatu Ylonen , Espoo, Finland * All rights reserved * * As far as I am concerned, the code I have written for this software * can be used freely for any purpose. Any derived versions of this * software must be clearly marked as such, and if the derived work is * incompatible with the protocol description in the RFC file, it must be * called by a name other than "ssh" or "Secure Shell". ***************************************************************************** * Copyright (c) 2000 Markus Friedl. All rights reserved. * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions * are met: * 1. Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. * 2. Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution. * * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT, * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF * THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. \*****************************************************************************/ /* ** MT safe */ #define _GNU_SOURCE #include "config.h" #if HAVE_SYS_PRCTL_H # include #endif #include #include #include #include #include #include #include #include #include #include #include #include "slurm/slurm_errno.h" #include "src/common/fd.h" #include "src/common/log.h" #include "src/common/macros.h" #include "src/common/slurm_protocol_api.h" #include "src/common/slurm_time.h" #include "src/common/xmalloc.h" #include "src/common/xstring.h" #include "src/slurmctld/slurmctld.h" #ifndef LINEBUFSIZE # define LINEBUFSIZE 256 #endif #define NAMELEN 16 #define LOG_MACRO(level, sched, fmt) { \ if ((level <= highest_log_level) || \ (sched && (level <= highest_sched_log_level))) { \ va_list ap; \ va_start(ap, fmt); \ _log_msg(level, sched, false, fmt, ap); \ va_end(ap); \ } \ } /* ** Define slurm-specific aliases for use by plugins, see slurm_xlator.h ** for details. */ strong_alias(get_log_level, slurm_get_log_level); strong_alias(get_sched_log_level, slurm_get_sched_log_level); strong_alias(log_init, slurm_log_init); strong_alias(log_reinit, slurm_log_reinit); strong_alias(log_fini, slurm_log_fini); strong_alias(log_alter, slurm_log_alter); strong_alias(log_alter_with_fp, slurm_log_alter_with_fp); strong_alias(log_set_fpfx, slurm_log_set_fpfx); strong_alias(log_fp, slurm_log_fp); strong_alias(log_oom, slurm_log_oom); strong_alias(log_has_data, slurm_log_has_data); strong_alias(log_flush, slurm_log_flush); strong_alias(log_var, slurm_log_var); strong_alias(fatal, slurm_fatal) __attribute__((noreturn)); strong_alias(fatal_abort, slurm_fatal_abort) __attribute__((noreturn)); strong_alias(error, slurm_error); strong_alias(spank_log, slurm_spank_log); strong_alias(info, slurm_info); strong_alias(verbose, slurm_verbose); strong_alias(sched_error, slurm_sched_error); strong_alias(sched_info, slurm_sched_info); strong_alias(sched_verbose, slurm_sched_verbose); /* ** struct defining a "log" type */ typedef struct { char *argv0; char *fpfx; /* optional prefix for logfile entries */ FILE *logfp; /* log file pointer */ cbuf_t *buf; /* stderr data buffer */ cbuf_t *fbuf; /* logfile data buffer */ log_facility_t facility; log_options_t opt; unsigned initialized:1; uint16_t fmt; /* Flag for specifying timestamp format */ uint64_t debug_flags; } log_t; char *slurm_prog_name = NULL; /* static variables */ static pthread_mutex_t log_lock = PTHREAD_MUTEX_INITIALIZER; static log_t *log = NULL; static log_t *sched_log = NULL; static volatile log_level_t highest_log_level = LOG_LEVEL_END; static volatile log_level_t highest_sched_log_level = LOG_LEVEL_QUIET; #define LOG_INITIALIZED ((log != NULL) && (log->initialized)) #define SCHED_LOG_INITIALIZED ((sched_log != NULL) && (sched_log->initialized)) /* define a default argv0 */ #if HAVE_PROGRAM_INVOCATION_NAME /* This used to use program_invocation_short_name, but on some systems * that gets truncated at 16 bytes, too short for our needs. */ extern char * program_invocation_name; # define default_name program_invocation_name #else # define default_name "" #endif /* * pthread_atfork handlers: */ static void _atfork_prep() { slurm_mutex_lock(&log_lock); } static void _atfork_parent() { slurm_mutex_unlock(&log_lock); } static void _atfork_child() { slurm_mutex_unlock(&log_lock); } static bool at_forked = false; #define atfork_install_handlers() \ while (!at_forked) { \ pthread_atfork(_atfork_prep, _atfork_parent, _atfork_child); \ at_forked = true; \ } static void _log_flush(log_t *log); static log_level_t _highest_level(log_level_t a, log_level_t b, log_level_t c) { if (a >= b) { return (a >= c) ? a : c; } else { return (b >= c) ? b : c; } } /* Write the current local time into the provided buffer. Returns the * number of characters written into the buffer. */ static size_t _make_timestamp(char *timestamp_buf, size_t max, const char *timestamp_fmt) { time_t timestamp_t = time(NULL); struct tm timestamp_tm; if (!localtime_r(×tamp_t, ×tamp_tm)) { fprintf(stderr, "localtime_r() failed\n"); return 0; } return strftime(timestamp_buf, max, timestamp_fmt, ×tamp_tm); } size_t rfc2822_timestamp(char *s, size_t max) { return _make_timestamp(s, max, "%a, %d %b %Y %H:%M:%S %z"); } size_t log_timestamp(char *s, size_t max) { if (!log) return _make_timestamp(s, max, "%Y-%m-%dT%T"); switch (log->fmt) { case LOG_FMT_RFC5424_MS: case LOG_FMT_RFC5424: { size_t written = _make_timestamp(s, max, "%Y-%m-%dT%T%z"); if (max >= 26 && written == 24) { /* The strftime %z format creates timezone offsets of * the form (+/-)hhmm, whereas the RFC 5424 format is * (+/-)hh:mm. So shift the minutes one step back and * insert the semicolon. */ s[25] = '\0'; s[24] = s[23]; s[23] = s[22]; s[22] = ':'; return written + 1; } return written; } case LOG_FMT_SHORT: return _make_timestamp(s, max, "%b %d %T"); break; default: return _make_timestamp(s, max, "%Y-%m-%dT%T"); break; } } /* check to see if a file is writeable, * RET 1 if file can be written now, * 0 if can not be written to within 5 seconds * -1 if file has been closed POLLHUP */ static int _fd_writeable(int fd) { struct pollfd ufds; struct stat stat_buf; int write_timeout = 5000; int rc; char temp[2]; ufds.fd = fd; ufds.events = POLLOUT; while ((rc = poll(&ufds, 1, write_timeout)) < 0) { switch (errno) { case EINTR: case EAGAIN: continue; default: return -1; } } if (rc == 0) return 0; /* * Check here to make sure that if this is a socket that it really * is still connected. If not then exit out and notify the sender. * This is here since a write doesn't always tell you the socket is * gone, but getting 0 back from a nonblocking read means just that. */ if ((ufds.revents & POLLHUP) || fstat(fd, &stat_buf) || ((S_ISSOCK(stat_buf.st_mode) && (rc = recv(fd, &temp, 1, MSG_DONTWAIT) <= 0) && ((rc == 0) || ((errno != EAGAIN) && (errno != EWOULDBLOCK)))))) return -1; else if ((ufds.revents & POLLNVAL) || (ufds.revents & POLLERR) || !(ufds.revents & POLLOUT)) return 0; /* revents == POLLOUT */ return 1; } /* * Initialize log with * prog = program name to tag error messages with * opt = log_options_t specifying max log levels for syslog, stderr, and file * fac = log facility for syslog (unused if syslog level == LOG_QUIET) * logfile = * logfile name if logfile level > LOG_QUIET */ static int _log_init(char *prog, log_options_t opt, log_facility_t fac, char *logfile ) { int rc = 0; if (!log) { log = xmalloc(sizeof(log_t)); log->logfp = NULL; log->argv0 = NULL; log->buf = NULL; log->fbuf = NULL; log->fpfx = NULL; atfork_install_handlers(); } if (prog) { if (log->argv0) xfree(log->argv0); log->argv0 = xstrdup(xbasename(prog)); } else if (!log->argv0) { const char *short_name = strrchr(default_name, '/'); if (short_name) short_name++; else short_name = default_name; log->argv0 = xstrdup(short_name); } /* Only take the first one here. In some situations it can change. */ if (!slurm_prog_name && log->argv0 && (strlen(log->argv0) > 0)) slurm_prog_name = xstrdup(log->argv0); if (!log->fpfx) log->fpfx = xstrdup(""); log->opt = opt; if (log->buf) { cbuf_destroy(log->buf); log->buf = NULL; } if (log->fbuf) { cbuf_destroy(log->fbuf); log->fbuf = NULL; } if (log->opt.buffered) { log->buf = cbuf_create(128, 8192); log->fbuf = cbuf_create(128, 8192); } if (log->opt.syslog_level > LOG_LEVEL_QUIET) log->facility = fac; if (logfile && (log->opt.logfile_level > LOG_LEVEL_QUIET)) { int mode = O_CREAT | O_WRONLY | O_APPEND | O_CLOEXEC; int fd; FILE *fp; fd = open(logfile, mode, S_IRUSR | S_IWUSR); if (fd >= 0) fp = fdopen(fd, "a"); if ((fd < 0) || !fp) { char *errmsg = slurm_strerror(errno); fprintf(stderr, "%s: %s: Unable to open logfile `%s': %s\n", prog, __func__, logfile, errmsg); if (fd >= 0) close(fd); rc = errno; goto out; } if (log->logfp) fclose(log->logfp); /* Ignore errors */ log->logfp = fp; } if (log->logfp && (fileno(log->logfp) < 0)) log->logfp = NULL; highest_log_level = _highest_level(log->opt.syslog_level, log->opt.logfile_level, log->opt.stderr_level); log->initialized = 1; out: return rc; } /* * Initialize scheduler log with * prog = program name to tag error messages with * opt = log_options_t specifying max log levels for syslog, stderr, and file * fac = log facility for syslog (unused if syslog level == LOG_QUIET) * logfile = logfile name if logfile level > LOG_QUIET */ static int _sched_log_init(char *prog, log_options_t opt, log_facility_t fac, char *logfile) { int rc = 0; if (!sched_log) { sched_log = xmalloc(sizeof(log_t)); atfork_install_handlers(); } if (prog) { xfree(sched_log->argv0); sched_log->argv0 = xstrdup(xbasename(prog)); } else if (!sched_log->argv0) { const char *short_name; short_name = strrchr((const char *) default_name, '/'); if (short_name) short_name++; else short_name = default_name; sched_log->argv0 = xstrdup(short_name); } if (!sched_log->fpfx) sched_log->fpfx = xstrdup(""); sched_log->opt = opt; if (sched_log->buf) { cbuf_destroy(sched_log->buf); sched_log->buf = NULL; } if (sched_log->fbuf) { cbuf_destroy(sched_log->fbuf); sched_log->fbuf = NULL; } if (sched_log->opt.buffered) { sched_log->buf = cbuf_create(128, 8192); sched_log->fbuf = cbuf_create(128, 8192); } if (sched_log->opt.syslog_level > LOG_LEVEL_QUIET) sched_log->facility = fac; if (logfile) { int mode = O_CREAT | O_WRONLY | O_APPEND | O_CLOEXEC; int fd; FILE *fp; fd = open(logfile, mode, S_IRUSR | S_IWUSR); if (fd >= 0) fp = fdopen(fd, "a"); if ((fd < 0) || !fp) { char *errmsg = slurm_strerror(errno); fprintf(stderr, "%s: %s: Unable to open logfile `%s': %s\n", prog, __func__, logfile, errmsg); if (fd >= 0) close(fd); rc = errno; goto out; } if (sched_log->logfp) fclose(sched_log->logfp); /* Ignore errors */ sched_log->logfp = fp; } if (sched_log->logfp && (fileno(sched_log->logfp) < 0)) sched_log->logfp = NULL; highest_sched_log_level = _highest_level(sched_log->opt.syslog_level, sched_log->opt.logfile_level, sched_log->opt.stderr_level); /* * The sched_log_level is (ab)used as a boolean. Force it to the end * if set so that the LOG_MACRO checks at least stay relatively clean, * and it's easier for us to introduce the idea of this log level * varying in the future. */ if (highest_sched_log_level > LOG_LEVEL_QUIET) highest_sched_log_level = LOG_LEVEL_END; sched_log->initialized = 1; out: return rc; } /* initialize log mutex, then initialize log data structures */ int log_init(char *prog, log_options_t opt, log_facility_t fac, char *logfile) { int rc = 0; slurm_mutex_lock(&log_lock); rc = _log_init(prog, opt, fac, logfile); slurm_mutex_unlock(&log_lock); return rc; } /* initialize log mutex, then initialize scheduler log data structures */ int sched_log_init(char *prog, log_options_t opt, log_facility_t fac, char *logfile) { int rc = 0; slurm_mutex_lock(&log_lock); rc = _sched_log_init(prog, opt, fac, logfile); slurm_mutex_unlock(&log_lock); if (rc) fatal("sched_log_alter could not open %s: %m", logfile); return rc; } void log_fini(void) { if (!log) return; slurm_mutex_lock(&log_lock); _log_flush(log); xfree(log->argv0); xfree(log->fpfx); if (log->buf) cbuf_destroy(log->buf); if (log->fbuf) cbuf_destroy(log->fbuf); if (log->logfp) fclose(log->logfp); xfree(log); xfree(slurm_prog_name); slurm_mutex_unlock(&log_lock); } void sched_log_fini(void) { if (!sched_log) return; slurm_mutex_lock(&log_lock); _log_flush(sched_log); xfree(sched_log->argv0); xfree(sched_log->fpfx); if (sched_log->buf) cbuf_destroy(sched_log->buf); if (sched_log->fbuf) cbuf_destroy(sched_log->fbuf); if (sched_log->logfp) fclose(sched_log->logfp); xfree(sched_log); slurm_mutex_unlock(&log_lock); } void log_reinit(void) { slurm_mutex_init(&log_lock); } void log_set_fpfx(char **prefix) { slurm_mutex_lock(&log_lock); xfree(log->fpfx); if (!prefix || !*prefix) log->fpfx = xstrdup(""); else { log->fpfx = *prefix; *prefix = NULL; } slurm_mutex_unlock(&log_lock); } void log_set_argv0(char *argv0) { slurm_mutex_lock(&log_lock); if (log->argv0) xfree(log->argv0); if (!argv0) log->argv0 = xstrdup(""); else log->argv0 = xstrdup(argv0); slurm_mutex_unlock(&log_lock); } /* reinitialize log data structures. Like log_init, but do not init * the log mutex */ int log_alter(log_options_t opt, log_facility_t fac, char *logfile) { int rc = 0; slurm_mutex_lock(&log_lock); rc = _log_init(NULL, opt, fac, logfile); slurm_mutex_unlock(&log_lock); log_set_debug_flags(); return rc; } /* log_set_debug_flags() * Set or reset the debug flags based on the configuration * file or the scontrol command. */ void log_set_debug_flags(void) { uint64_t debug_flags = slurm_get_debug_flags(); slurm_mutex_lock(&log_lock); log->debug_flags = debug_flags; slurm_mutex_unlock(&log_lock); } /* reinitialize log data structures. Like log_init, but do not init * the log mutex */ int log_alter_with_fp(log_options_t opt, log_facility_t fac, FILE *fp_in) { int rc = 0; slurm_mutex_lock(&log_lock); rc = _log_init(NULL, opt, fac, NULL); if (log->logfp) fclose(log->logfp); /* Ignore errors */ log->logfp = fp_in; if (log->logfp) { int fd; if ((fd = fileno(log->logfp)) < 0) log->logfp = NULL; /* don't close fd on out since this fd was made * outside of the logger */ } slurm_mutex_unlock(&log_lock); return rc; } /* reinitialize scheduler log data structures. Like sched_log_init, * but do not init the log mutex */ int sched_log_alter(log_options_t opt, log_facility_t fac, char *logfile) { int rc = 0; slurm_mutex_lock(&log_lock); rc = _sched_log_init(NULL, opt, fac, logfile); slurm_mutex_unlock(&log_lock); if (rc) fatal("sched_log_alter could not open %s: %m", logfile); return rc; } /* Return the FILE * of the current logfile (or stderr if not logging to * a file, but NOT both). Also see log_oom() below. */ FILE *log_fp(void) { FILE *fp; slurm_mutex_lock(&log_lock); if (log && log->logfp) { fp = log->logfp; } else fp = stderr; slurm_mutex_unlock(&log_lock); return fp; } /* Log out of memory without message buffering */ void log_oom(const char *file, int line, const char *func) { if (log && log->logfp) { fprintf(log->logfp, "%s:%d: %s: malloc failed\n", file, line, func); } if (!log || log->opt.stderr_level) { fprintf(stderr, "%s:%d: %s: malloc failed\n", file, line, func); } } /* Set the timestamp format flag */ void log_set_timefmt(unsigned fmtflag) { if (log) { slurm_mutex_lock(&log_lock); log->fmt = fmtflag; slurm_mutex_unlock(&log_lock); } else { fprintf(stderr, "%s:%d: %s Slurm log not initialized\n", __FILE__, __LINE__, __func__); } } /* * _set_idbuf() * Write in the input buffer the current time and milliseconds * the process id and the current thread id. */ static void _set_idbuf(char *idbuf, size_t size) { struct timeval now; char time[25]; char thread_name[NAMELEN]; int max_len = 12; /* handles current longest thread name */ gettimeofday(&now, NULL); #if HAVE_SYS_PRCTL_H if (prctl(PR_GET_NAME, thread_name, NULL, NULL, NULL) < 0) { error("failed to get thread name: %m"); max_len = 0; thread_name[0] = '\0'; } #else /* skip printing thread name if not available */ max_len = 0; thread_name[0] = '\0'; #endif slurm_ctime2_r(&now.tv_sec, time); snprintf(idbuf, size, "%.15s.%-6d %5d %-*s %p", time + 4, (int) now.tv_usec, (int) getpid(), max_len, thread_name, (void *) pthread_self()); } /* * jobid2fmt() - print a job ID as "JobId=..." including, as applicable, * the job array or hetjob component information with the raw jobid in * parenthesis. */ static char *_jobid2fmt(job_record_t *job_ptr, char *buf, int buf_size) { /* * NOTE: You will notice we put a %.0s in front of the string. * This is to handle the fact that we can't remove the job_ptr * argument from the va_list directly. So when we call vsnprintf() * to handle the va_list this will effectively skip this argument. */ if (job_ptr == NULL) return "%.0sJobId=Invalid"; if (job_ptr->magic != JOB_MAGIC) return "%.0sJobId=CORRUPT"; if (job_ptr->het_job_id) { snprintf(buf, buf_size, "%%.0sJobId=%u+%u(%u)", job_ptr->het_job_id, job_ptr->het_job_offset, job_ptr->job_id); } else if (job_ptr->array_recs && (job_ptr->array_task_id == NO_VAL)) { snprintf(buf, buf_size, "%%.0sJobId=%u_*", job_ptr->array_job_id); } else if (job_ptr->array_task_id == NO_VAL) { snprintf(buf, buf_size, "%%.0sJobId=%u", job_ptr->job_id); } else { snprintf(buf, buf_size, "%%.0sJobId=%u_%u(%u)", job_ptr->array_job_id, job_ptr->array_task_id, job_ptr->job_id); } return buf; } /* * stepid2fmt() - print a step ID as " StepId=...", with Batch and Extern * used as appropriate. * Note that the "%.0s" trick is already included by jobid2fmt above, and * should not be repeated here. */ static char *_stepid2fmt(step_record_t *step_ptr, char *buf, int buf_size) { if (step_ptr == NULL) return " StepId=Invalid"; if (step_ptr->magic != STEP_MAGIC) return " StepId=CORRUPT"; if (step_ptr->step_id == SLURM_EXTERN_CONT) { return " StepId=Extern"; } else if (step_ptr->step_id == SLURM_BATCH_SCRIPT) { return " StepId=Batch"; } else if (step_ptr->step_id == SLURM_PENDING_STEP) { return " StepId=TBD"; } else { snprintf(buf, buf_size, " StepId=%u", step_ptr->step_id); } return buf; } /* * return a heap allocated string formed from fmt and ap arglist * returned string is allocated with xmalloc, so must free with xfree. * * args are like printf, with the addition of the following format chars: * - %m expands to strerror(errno) * - %M expand to time stamp, format is configuration dependent * - %pJ expands to "JobId=XXXX" for the given job_ptr, with the appropriate * format for job arrays and hetjob components. * - %pS expands to "JobId=XXXX StepId=YYYY" for a given step_ptr. * - %t expands to strftime("%x %X") [ locally preferred short date/time ] * - %T expands to rfc2822 date time [ "dd, Mon yyyy hh:mm:ss GMT offset" ] * * these formats are expanded first, leaving all others to be passed to * vsnprintf() to complete the expansion using the ap arglist. */ static char *vxstrfmt(const char *fmt, va_list ap) { char *intermediate_fmt = NULL; char *out_string = NULL; char *p; bool found_other_formats = false; int cnt = 0; while (*fmt != '\0') { bool is_our_format = false; p = (char *)strchr(fmt, '%'); if (p == NULL) { /* * no more format sequences, append the rest of * fmt and exit the loop: */ xstrcat(intermediate_fmt, fmt); break; } /* * make sure it's one of our format specifiers, skipping * any that aren't: */ do { switch (*(p + 1)) { case 'm': case 't': case 'T': case 'M': is_our_format = true; break; case 'p': switch (*(p + 2)) { case 'J': case 'S': is_our_format = true; /* * Need to set found_other_formats to * still consume the %.0s if not other * format strings are included. */ found_other_formats = true; break; default: found_other_formats = true; break; } break; default: found_other_formats = true; break; } cnt++; } while (!is_our_format && (p = (char *)strchr(p + 1, '%'))); if (is_our_format) { char *substitute = NULL; char substitute_on_stack[256]; int should_xfree = 1; /* * p points to the leading % of one of our formats; * append anything from fmt up to p to the intermediate * format string: */ xstrncat(intermediate_fmt, fmt, p - fmt); fmt = p + 1; /* * fill the substitute buffer with whatever text we want * to substitute for the format sequence in question: */ switch (*fmt) { case 'p': fmt++; switch (*fmt) { case 'J': /* "%pJ" => "JobId=..." */ { int i; void *ptr = NULL; job_record_t *job_ptr; va_list ap_copy; va_copy(ap_copy, ap); for (i = 0; i < cnt; i++ ) ptr = va_arg(ap_copy, void *); job_ptr = ptr; xstrcat(intermediate_fmt, _jobid2fmt( job_ptr, substitute_on_stack, sizeof(substitute_on_stack))); va_end(ap_copy); break; } /* "%pS" => "JobId=... StepId=..." */ case 'S': { int i; void *ptr = NULL; step_record_t *step_ptr = NULL; job_record_t *job_ptr = NULL; va_list ap_copy; va_copy(ap_copy, ap); for (i = 0; i < cnt; i++ ) ptr = va_arg(ap_copy, void *); step_ptr = ptr; if (step_ptr && (step_ptr->magic == STEP_MAGIC)) job_ptr = step_ptr->job_ptr; xstrcat(intermediate_fmt, _jobid2fmt( job_ptr, substitute_on_stack, sizeof(substitute_on_stack))); xstrcat(intermediate_fmt, _stepid2fmt( step_ptr, substitute_on_stack, sizeof(substitute_on_stack))); va_end(ap_copy); break; } default: /* Unknown */ break; } break; case 'm': /* "%m" => strerror(errno) */ substitute = slurm_strerror(errno); should_xfree = 0; break; case 't': /* "%t" => locally preferred date/time*/ xstrftimecat(substitute, "%x %X"); break; case 'T': /* "%T" => "dd, Mon yyyy hh:mm:ss off" */ xstrftimecat(substitute, "%a, %d %b %Y %H:%M:%S %z"); break; case 'M': if (!log) { xiso8601timecat(substitute, true); break; } switch (log->fmt) { case LOG_FMT_ISO8601_MS: /* "%M" => "yyyy-mm-ddThh:mm:ss.fff" */ xiso8601timecat(substitute, true); break; case LOG_FMT_ISO8601: /* "%M" => "yyyy-mm-ddThh:mm:ss.fff" */ xiso8601timecat(substitute, false); break; case LOG_FMT_RFC5424_MS: /* "%M" => "yyyy-mm-ddThh:mm:ss.fff(+/-)hh:mm" */ xrfc5424timecat(substitute, true); break; case LOG_FMT_RFC5424: /* "%M" => "yyyy-mm-ddThh:mm:ss.fff(+/-)hh:mm" */ xrfc5424timecat(substitute, false); break; case LOG_FMT_CLOCK: /* "%M" => "usec" */ #if defined(__FreeBSD__) snprintf(substitute_on_stack, sizeof(substitute_on_stack), "%d", clock()); #else snprintf(substitute_on_stack, sizeof(substitute_on_stack), "%ld", clock()); #endif substitute = substitute_on_stack; should_xfree = 0; break; case LOG_FMT_SHORT: /* "%M" => "Mon DD hh:mm:ss" */ xstrftimecat(substitute, "%b %d %T"); break; case LOG_FMT_THREAD_ID: _set_idbuf(substitute_on_stack, sizeof(substitute_on_stack)); substitute = substitute_on_stack; should_xfree = 0; break; } break; } fmt++; if (substitute) { char *s = substitute; while (*s && (p = (char *)strchr(s, '%'))) { /* append up through the '%' */ xstrncat(intermediate_fmt, s, p - s); xstrcat(intermediate_fmt, "%%"); s = p + 1; } if (*s) { /* append whatever's left of the substitution: */ xstrcat(intermediate_fmt, s); } /* deallocate substitute if necessary: */ if (should_xfree) { xfree(substitute); } } } else { /* * no more format sequences for us, append the rest of * fmt and exit the loop: */ xstrcat(intermediate_fmt, fmt); break; } } if (intermediate_fmt && found_other_formats) { char tmp[LINEBUFSIZE]; int actual_len; va_list ap_copy; va_copy(ap_copy, ap); actual_len = vsnprintf(tmp, sizeof(tmp), intermediate_fmt, ap_copy); va_end(ap_copy); if (actual_len >= 0) { if (actual_len < sizeof(tmp)) { out_string = xstrdup(tmp); } else { /* * our C library's vsnprintf() was nice enough * to return the necessary size of the buffer! */ out_string = xmalloc(actual_len + 1); if (out_string) { va_copy(ap_copy, ap); vsnprintf(out_string, actual_len + 1, intermediate_fmt, ap_copy); va_end(ap_copy); } } } else { size_t growable_tmp_size = LINEBUFSIZE; char *growable_tmp = NULL; /* * our C library's vsnprintf() doesn't return the * necessary buffer size on overflow, it considers that * an error condition. So we need to iteratively grow * a buffer until it accommodates the vsnprintf() call */ do { growable_tmp_size += LINEBUFSIZE; growable_tmp = xrealloc(growable_tmp, growable_tmp_size); if (!growable_tmp) break; va_copy(ap_copy, ap); actual_len = vsnprintf(growable_tmp, growable_tmp_size, intermediate_fmt, ap_copy); va_end(ap_copy); } while (actual_len < 0); out_string = growable_tmp; } xfree(intermediate_fmt); } else if (intermediate_fmt) { /* * no additional format sequences, so we can just return the * intermediate_fmt string */ out_string = intermediate_fmt; } return out_string; } /* * concatenate result of xstrfmt() to dst, expanding dst if necessary */ static void xlogfmtcat(char **dst, const char *fmt, ...) { va_list ap; char *buf = NULL; va_start(ap, fmt); buf = vxstrfmt(fmt, ap); va_end(ap); xstrcat(*dst, buf); xfree(buf); } static void _log_printf(log_t *log, cbuf_t *cb, FILE *stream, const char *fmt, ...) { va_list ap; int fd = -1; /* If the fd is less than 0 just return since we can't do anything here. * This can happen if a calling program is the one that set up the io. */ if (stream) fd = fileno(stream); if (fd < 0) return; /* If the socket has gone away we just return like all is well. */ if (_fd_writeable(fd) != 1) return; va_start(ap, fmt); if (log->opt.buffered && (cb != NULL)) { char *buf = vxstrfmt(fmt, ap); int len = strlen(buf); int dropped; cbuf_write(cb, buf, len, &dropped); cbuf_read_to_fd(cb, fd, -1); xfree(buf); } else { vfprintf(stream, fmt, ap); } va_end(ap); } /* * log a message at the specified level to facilities that have been * configured to receive messages at that level */ static void _log_msg(log_level_t level, bool sched, bool spank, const char *fmt, va_list args) { char *pfx = ""; char *buf = NULL; char *msgbuf = NULL; int priority = LOG_INFO; slurm_mutex_lock(&log_lock); if (!LOG_INITIALIZED) { log_options_t opts = LOG_OPTS_STDERR_ONLY; _log_init(NULL, opts, 0, NULL); } if (SCHED_LOG_INITIALIZED && sched && (highest_sched_log_level > LOG_LEVEL_QUIET)) { buf = vxstrfmt(fmt, args); xlogfmtcat(&msgbuf, "[%M] %s%s%s", sched_log->fpfx, pfx, buf); _log_printf(sched_log, sched_log->fbuf, sched_log->logfp, "sched: %s\n", msgbuf); fflush(sched_log->logfp); xfree(msgbuf); } if (level > highest_log_level) { slurm_mutex_unlock(&log_lock); xfree(buf); return; } if (log->opt.prefix_level || (log->opt.syslog_level > level)) { switch (level) { case LOG_LEVEL_FATAL: priority = LOG_CRIT; pfx = "fatal: "; break; case LOG_LEVEL_ERROR: priority = LOG_ERR; pfx = sched? "error: sched: " : "error: "; pfx = spank ? "" : pfx; break; case LOG_LEVEL_INFO: case LOG_LEVEL_VERBOSE: priority = LOG_INFO; pfx = sched ? "sched: " : ""; break; case LOG_LEVEL_DEBUG: priority = LOG_DEBUG; pfx = sched ? "debug: sched: " : "debug: "; break; case LOG_LEVEL_DEBUG2: priority = LOG_DEBUG; pfx = sched ? "debug2: sched: " : "debug2: "; break; case LOG_LEVEL_DEBUG3: priority = LOG_DEBUG; pfx = sched ? "debug3: sched: " : "debug3: "; break; case LOG_LEVEL_DEBUG4: priority = LOG_DEBUG; pfx = "debug4: "; break; case LOG_LEVEL_DEBUG5: priority = LOG_DEBUG; pfx = "debug5: "; break; default: priority = LOG_ERR; pfx = "internal error: "; break; } } if (!buf) { /* format the basic message, * if not already done for scheduling log */ buf = vxstrfmt(fmt, args); } if (level <= log->opt.stderr_level) { fflush(stdout); if (spank) { _log_printf(log, log->buf, stderr, "%s\n", buf); } else if (log->fmt == LOG_FMT_THREAD_ID) { char tmp[64]; _set_idbuf(tmp, sizeof(tmp)); _log_printf(log, log->buf, stderr, "%s: %s%s\n", tmp, pfx, buf); } else { _log_printf(log, log->buf, stderr, "%s: %s%s\n", log->argv0, pfx, buf); } fflush(stderr); } if ((level <= log->opt.logfile_level) && (log->logfp != NULL)) { xlogfmtcat(&msgbuf, "[%M] %s%s%s", log->fpfx, pfx, buf); _log_printf(log, log->fbuf, log->logfp, "%s\n", msgbuf); fflush(log->logfp); xfree(msgbuf); } if (level <= log->opt.syslog_level) { /* Avoid changing errno if syslog fails */ int orig_errno = slurm_get_errno(); xlogfmtcat(&msgbuf, "%s%s", pfx, buf); openlog(log->argv0, LOG_PID, log->facility); syslog(priority, "%.500s", msgbuf); closelog(); slurm_seterrno(orig_errno); xfree(msgbuf); } slurm_mutex_unlock(&log_lock); xfree(buf); } bool log_has_data() { bool rc = false; slurm_mutex_lock(&log_lock); if (log->opt.buffered) rc = (cbuf_used(log->buf) > 0); slurm_mutex_unlock(&log_lock); return rc; } static void _log_flush(log_t *log) { if (!log->opt.buffered) return; if (log->opt.stderr_level) cbuf_read_to_fd(log->buf, fileno(stderr), -1); else if (log->logfp && (fileno(log->logfp) > 0)) cbuf_read_to_fd(log->fbuf, fileno(log->logfp), -1); } void log_flush() { slurm_mutex_lock(&log_lock); _log_flush(log); slurm_mutex_unlock(&log_lock); } /* * attempt to log message and exit() */ void fatal(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_FATAL, false, fmt); log_flush(); exit(1); } /* * attempt to log message and exit() */ void fatal_abort(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_FATAL, false, fmt); log_flush(); abort(); } /* * Attempt to log message at a variable log level */ void log_var(const log_level_t log_lvl, const char *fmt, ...) { LOG_MACRO(log_lvl, false, fmt); if (log_lvl == LOG_LEVEL_FATAL) { log_flush(); exit(1); } } void sched_log_var(const log_level_t log_lvl, const char *fmt, ...) { LOG_MACRO(log_lvl, true, fmt); if (log_lvl == LOG_LEVEL_FATAL) { log_flush(); exit(1); } } int error(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_ERROR, false, fmt); /* * Return SLURM_ERROR so calling functions can * do "return error (...);" */ return SLURM_ERROR; } /* * Like error(), but printed without the error: prefix so SPANK plugins * can have a convenient way to return messages to the user. */ void spank_log(const char *fmt, ...) { va_list ap; va_start(ap, fmt); _log_msg(LOG_LEVEL_ERROR, false, true, fmt, ap); va_end(ap); } void info(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_INFO, false, fmt); } void verbose(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_VERBOSE, false, fmt); } void slurm_debug(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_DEBUG, false, fmt); } void slurm_debug2(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_DEBUG2, false, fmt); } void slurm_debug3(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_DEBUG3, false, fmt); } /* * Debug levels higher than debug3 are not written to stderr in the * slurmstepd process after stderr is connected back to the client (srun). */ void slurm_debug4(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_DEBUG4, false, fmt); } void slurm_debug5(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_DEBUG5, false, fmt); } int sched_error(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_ERROR, true, fmt); /* * Return SLURM_ERROR so calling functions can * do "return error (...);" */ return SLURM_ERROR; } void sched_info(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_INFO, true, fmt); } void sched_verbose(const char *fmt, ...) { LOG_MACRO(LOG_LEVEL_VERBOSE, true, fmt); } /* Return the highest LOG_LEVEL_* used for any logging mechanism. * For example, if LOG_LEVEL_INFO is returned, we know that all verbose and * debug type messages will be ignored. */ extern int get_log_level(void) { return highest_log_level; } extern int get_sched_log_level(void) { return MAX(highest_log_level, highest_sched_log_level); }