src/common/log.c

/*****************************************************************************\
 *  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 <mgrondona@llnl.gov>
 *  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 <ylo@cs.hut.fi>
 * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, 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 <sys/prctl.h>
#endif

#include <arpa/inet.h>
#include <errno.h>
#include <poll.h>
#include <pthread.h>
#include <stdarg.h>
#include <stdio.h>
#include <string.h>
#include <sys/socket.h>
#include <sys/stat.h>
#include <sys/time.h>
#include <sys/types.h>
#include <sys/un.h>
#include <unistd.h>

#include "slurm/slurm_errno.h"
#include "src/common/data.h"
#include "src/common/fd.h"
#include "src/common/log.h"
#include "src/common/macros.h"
#include "src/common/sluid.h"
#include "src/common/slurm_protocol_api.h"
#include "src/common/slurm_time.h"
#include "src/common/threadpool.h"
#include "src/common/xmalloc.h"
#include "src/common/xstring.h"

#include "src/interfaces/serializer.h"

#include "src/slurmctld/slurmctld.h"


#ifndef LINEBUFSIZE
#  define LINEBUFSIZE 256
#endif

/* Field width the thread name is padded to in the "%M" prefix */
#define THREAD_NAME_WIDTH 12

#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, 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_prefix,	slurm_log_set_prefix);
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(sched_error,	slurm_sched_error);
strong_alias(sched_info,	slurm_sched_info);
strong_alias(sched_verbose,	slurm_sched_verbose);
strong_alias(vxstrfmt, slurm_vxstrfmt);

/*
** struct defining a "log" type
*/
typedef struct {
	char *argv0;
	char *prefix;            /* optional prefix with log_set_prefix */
	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;
	bool initialized;
	log_flags_t flags; /* Options accompanying the timestamp format */
	log_fmt_t fmt; /* Timestamp format */
}	log_t;

/* static variables */
static pthread_mutex_t  log_lock = PTHREAD_MUTEX_INITIALIZER;
static log_t            *log = NULL;
static log_t            *sched_log = NULL;
static bool syslog_open = false;
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(void) { slurm_mutex_lock(&log_lock); }
static void _atfork_parent(void) { slurm_mutex_unlock(&log_lock); }
static void _atfork_child(void) { 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(&timestamp_t, &timestamp_tm)) {
		fprintf(stderr, "localtime_r() failed\n");
		return 0;
	}
	return strftime(timestamp_buf, max, timestamp_fmt, &timestamp_tm);
}

size_t rfc2822_timestamp(char *s, size_t max)
{
	return _make_timestamp(s, max, "%a, %d %b %Y %H:%M:%S %z");
}

static size_t _fix_tz(char *s, size_t max, size_t written)
{
	xassert(written == 24);
	xassert(max >= 26);

	if ((max < 26) || (written != 24))
		return written;

	/*
	 * 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 25;
}

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_US:
	case LOG_FMT_RFC5424:
	{
		size_t written = _make_timestamp(s, max, "%Y-%m-%dT%T%z");
		return _fix_tz(s, max, written);
	}
	case LOG_FMT_RFC3339:
	{
		size_t written = _make_timestamp(s, max, "%FT%T%z");
		return _fix_tz(s, max, 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;
	int write_timeout = 5000;
	int rc;

	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;

	if (ufds.revents & POLLHUP)
		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->prefix = NULL;
		atfork_install_handlers();
	}

	if (syslog_open) {
		closelog();
		syslog_open = false;
	}

	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);
	}

	if (!log->prefix)
		log->prefix = 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(8192, true);
		log->fbuf = cbuf_create(8192, true);
	}

	if (log->opt.syslog_level > LOG_LEVEL_QUIET) {
		log->facility = fac;
		openlog(log->argv0, LOG_PID, log->facility);
		syslog_open = true;
	}

	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->prefix)
		sched_log->prefix = 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(8192, true);
		sched_log->fbuf = cbuf_create(8192, true);
	}

	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);
	if (syslog_open) {
		closelog();
		syslog_open = false;
	}
	xfree(log->argv0);
	xfree(log->prefix);
	if (log->buf)
		cbuf_destroy(log->buf);
	if (log->fbuf)
		cbuf_destroy(log->fbuf);
	if (log->logfp)
		fclose(log->logfp);
	xfree(log);
	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->prefix);
	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_prefix(char **prefix)
{
	slurm_mutex_lock(&log_lock);
	xfree(log->prefix);
	if (!prefix || !*prefix)
		log->prefix = xstrdup("");
	else {
		log->prefix = *prefix;
		*prefix = NULL;
	}
	slurm_mutex_unlock(&log_lock);
}

void log_set_argv0(char *argv0)
{
	slurm_mutex_lock(&log_lock);
	if (syslog_open) {
		closelog();
		syslog_open = false;
	}
	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);
	return rc;
}

/* 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 and the options accompanying it */
void log_set_timefmt(log_fmt_t fmt, log_flags_t flags)
{
	xassert(log);

	if (!log)
		return;

	slurm_mutex_lock(&log_lock);
	log->fmt = fmt;
	log->flags = flags;
	slurm_mutex_unlock(&log_lock);
}

/*
 * Write the process id and the current thread name and id into buf
 * IN/OUT buf - buffer holding whatever "%M" has rendered so far
 * IN size - bytes available in buf
 * IN used - bytes already written to buf, which a separator follows
 */
static void _set_thread_id(char *buf, size_t size, size_t used)
{
	char thread_name[PRCTL_BUF_BYTES] = { 0 };
	int max_len = THREAD_NAME_WIDTH;

#if HAVE_SYS_PRCTL_H
	if (prctl(PR_GET_NAME, thread_name, NULL, NULL, NULL) < 0) {
		fprintf(stderr, "failed to get thread name: %m\n");
		max_len = 0;
		thread_name[0] = '\0';
	}
#else
	/* skip printing thread name if not available */
	max_len = 0;
	thread_name[0] = '\0';
#endif

	snprintf((buf + used), (size - used), "%s%5d %-*s %p",
		 (used ? " " : ""), (int) getpid(), max_len, thread_name,
		 (void *) pthread_self());
}

/*
 * RET true if the "%M" specifier has anything to render, which is the only
 *	thing the log line prefix holds
 */
static bool _have_timefmt(void)
{
	if (log->fmt != LOG_FMT_OMIT)
		return true;

	/* omit drops the timestamp, not everything printed beside it */
	return (log->flags & LOG_FLAG_THREAD_ID);
}

/* Fractional second precision, which RFC 5424 allows no more of than usec */
typedef enum {
	RFC5424_NONE = 0,
	RFC5424_MSEC = 3,
	RFC5424_USEC = 6,
} rfc5424_prec_t;

/*
 * Write what "%M" stands for into buf: the timestamp named by the
 * LogTimeFormat timestamp format, and the process and thread when either the
 * option or the deprecated format asks for them
 * IN/OUT buf - buffer to write into
 * IN size - bytes available in buf
 *
 * Note: every timestamp format is the same strftime() call with an optional
 * fractional second and an optional timezone offset, so they share one
 * renderer.
 */
static void _set_timestamp(char *buf, size_t size)
{
	const char *date_fmt = "%Y-%m-%dT%T";
	const char *usec_fmt = ".%6.6d";
	rfc5424_prec_t prec = RFC5424_NONE;
	bool tz = false;
	timespec_t ts = { 0 };
	struct tm tm = { 0 };
	size_t used = 0;

	buf[0] = '\0';

	switch (log->fmt) {
	case LOG_FMT_ISO8601_MS:
		/* "%M" => "yyyy-mm-ddThh:mm:ss.fff" */
		prec = RFC5424_MSEC;
		break;
	case LOG_FMT_ISO8601:
		/* "%M" => "yyyy-mm-ddThh:mm:ss" */
		break;
	case LOG_FMT_RFC5424_MS:
		/* "%M" => "yyyy-mm-ddThh:mm:ss.fff(+/-)hh:mm" */
		prec = RFC5424_MSEC;
		tz = true;
		break;
	case LOG_FMT_RFC5424:
		/* "%M" => "yyyy-mm-ddThh:mm:ss(+/-)hh:mm" */
		tz = true;
		break;
	case LOG_FMT_RFC5424_US:
		/* "%M" => "yyyy-mm-ddThh:mm:ss.ffffff(+/-)hh:mm" */
		prec = RFC5424_USEC;
		tz = true;
		break;
	case LOG_FMT_RFC3339:
		/* "%M" => "yyyy-mm-ddThh:mm:ss(+/-)hh:mm" */
		tz = true;
		break;
	case LOG_FMT_CLOCK:
		/* "%M" => "usec" */
#if defined(__FreeBSD__)
		used = snprintf(buf, size, "%d", clock());
#else
		used = snprintf(buf, size, "%ld", clock());
#endif
		if (used >= size)
			used = (size - 1);

		goto thread_id;
	case LOG_FMT_SHORT:
		/* "%M" => "Mon DD hh:mm:ss" */
		date_fmt = "%b %d %T";
		break;
	case LOG_FMT_THREAD_ID:
		/*
		 * "%M" => "Mon DD hh:mm:ss.f     "
		 *
		 * The fraction is left justified rather than zero padded. That
		 * is not a well formed fractional second, but it is what this
		 * deprecated format has always printed, so keep it rather than
		 * change what an existing configuration writes.
		 */
		date_fmt = "%b %d %T";
		usec_fmt = ".%-6d";
		prec = RFC5424_USEC;
		break;
	case LOG_FMT_OMIT:
		/* omit drops the timestamp and nothing else */
		goto thread_id;
	}

	ts = timespec_now();

	if (!localtime_r(&ts.tv_sec, &tm))
		fprintf(stderr, "localtime_r() failed\n");

	if (!(used = strftime(buf, size, date_fmt, &tm))) {
		fprintf(stderr, "strftime() returned 0\n");
		buf[0] = '\0';
		goto thread_id;
	}

	switch (prec) {
	case RFC5424_NONE:
		break;
	case RFC5424_MSEC:
		used += snprintf((buf + used), (size - used), ".%3.3d",
				 (int) (ts.tv_nsec / NSEC_IN_MSEC));
		break;
	case RFC5424_USEC:
		used += snprintf((buf + used), (size - used), usec_fmt,
				 (int) (ts.tv_nsec / NSEC_IN_USEC));
		break;
	}

	/*
	 * snprintf() returns the length it wanted to write, so a truncated
	 * fraction would leave used past the end of buf.
	 */
	if (used >= size)
		used = (size - 1);

	if (tz) {
		char z[12] = "";

		/*
		 * strftime() writes the offset as (+/-)hhmm where RFC 5424
		 * writes it as (+/-)hh:mm, so shift the minutes one step back
		 * and insert the colon.
		 */
		if (!strftime(z, sizeof(z), "%z", &tm))
			fprintf(stderr, "strftime() returned 0\n");
		z[5] = z[4];
		z[4] = z[3];
		z[3] = ':';

		used += snprintf((buf + used), (size - used), "%s", z);

		if (used >= size)
			used = (size - 1);
	}

thread_id:
	/*
	 * The deprecated format prints the same fields as the option, so honor
	 * either of them.
	 */
	if ((log->flags & LOG_FLAG_THREAD_ID) ||
	    (log->fmt == LOG_FMT_THREAD_ID))
		_set_thread_id(buf, size, used);
}

/*
 * _addr2fmt() - print an IP address from slurm_addr_t
 */
static char *_addr2fmt(slurm_addr_t *addr_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 addr_ptr
	 * argument from the va_list directly. So when we call vsnprintf()
	 * to handle the va_list this will effectively skip this argument.
	 */
	if (addr_ptr == NULL)
		return "%.0sNULL";

	if (addr_ptr->ss_family == AF_INET6) {
		char addrbuf[INET6_ADDRSTRLEN];
		uint16_t port = 0;
		struct sockaddr_in6 *in6 = (struct sockaddr_in6 *) addr_ptr;
		inet_ntop(AF_INET6, &in6->sin6_addr, addrbuf, INET6_ADDRSTRLEN);
		port = ntohs(in6->sin6_port);
		snprintf(buf, buf_size, "[%%.0s%s]:%d", addrbuf, port);
	} else if (addr_ptr->ss_family == AF_INET) {
		char addrbuf[INET_ADDRSTRLEN];
		struct sockaddr_in *in = (struct sockaddr_in *) addr_ptr;
		uint16_t port = 0;
		inet_ntop(AF_INET, &in->sin_addr, addrbuf, INET_ADDRSTRLEN);
		port = ntohs(in->sin_port);
		snprintf(buf, buf_size, "%%.0s%s:%d", addrbuf, port);
	} else if (addr_ptr->ss_family == AF_UNIX) {
		struct sockaddr_un *un = (struct sockaddr_un *) addr_ptr;
		snprintf(buf, buf_size, "%%.0sunix:%s", un->sun_path);
	} else if (addr_ptr->ss_family == AF_UNSPEC) {
		/*
		 * AF_UNSPEC is place holder for unspecified which may be
		 * nothing or used as a wild card depending on the API call.
		 */
		snprintf(buf, buf_size, "%%.0sAF_UNSPEC");
	} else {
		snprintf(buf, buf_size, "%%.0sINVALID");
	}

	return buf;
}
/*
 * 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";

	return log_build_step_id_str(&step_ptr->step_id, buf, buf_size,
				     STEP_ID_FLAG_SPACE | STEP_ID_FLAG_NO_JOB);
}

static char *_auth_level2str(uint16_t auth_level)
{
	switch (auth_level) {
	case AUTH_LEVEL_OPERATOR:
		return ",Level=Operator";
		break;
	case AUTH_LEVEL_ADMIN:
		return ",Level=Administrator";
		break;
	case AUTH_LEVEL_INTERNAL:
		return ",Level=Internal";
		break;
	case AUTH_LEVEL_NOTSET:
	case AUTH_LEVEL_USER:
		break;
	}

	return "";
}

static char *_msgauth2fmt(slurm_msg_auth_t *msg_auth, char *buf, int buf_size)
{
	if (!msg_auth)
		return "%.0sUser=Invalid";

	if (msg_auth->username && (msg_auth->uid != SLURM_AUTH_NOBODY) &&
	    (msg_auth->uid != NO_VAL))
		snprintf(buf, buf_size, "%%.0sUser=%s (UID=%u%s)",
			 msg_auth->username, msg_auth->uid,
			 _auth_level2str(msg_auth->level));
	else if (msg_auth->username)
		snprintf(buf, buf_size, "%%.0sUser=%s (UID=Unknown%s)",
			 msg_auth->username, _auth_level2str(msg_auth->level));
	else
		snprintf(buf, buf_size, "%%.0sUser=Unknown (UID=%u%s)",
			 msg_auth->uid, _auth_level2str(msg_auth->level));

	return buf;
}

static char *_print_data_t(const data_t *d, char *buffer, int 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 data_t
	 * argument from the va_list directly. So when we call vsnprintf()
	 * to handle the va_list this will effectively skip this argument.
	 */
	snprintf(buffer, size, "%%.0s%s(0x%"PRIxPTR")",
		 data_get_type_string(d), ((uintptr_t) d));
	return buffer;
}

static char *_print_data_json(data_t *d, char *buffer, int size)
{
	char *nbuf = NULL;

	/*
	 * 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 data_t
	 * argument from the va_list directly. So when we call vsnprintf()
	 * to handle the va_list this will effectively skip this argument.
	 */
	if (serialize_g_data_to_string(&nbuf, NULL, d, MIME_TYPE_JSON,
				       SER_FLAGS_COMPACT))
		snprintf(buffer, size, "%%.0s(JSON serialization failed)");
	else
		snprintf(buffer, size, "%%.0s%s", nbuf);

	xfree(nbuf);

	return buffer;
}

static void _vxstrfmt_on_our_p_fmt(const char **fmt_ptr, va_list ap, int *cnt,
				   char **intermediate_fmt_ptr,
				   char **intermediate_pos_ptr,
				   char *substitute_on_stack,
				   const int substitute_on_stack_bytes)
{
	*fmt_ptr += 1;
	switch (**fmt_ptr) {
	case 'A': /* "%pA" -> "AAA.BBB.CCC.DDD:XXXX" */
	{
		void *ptr = NULL;
		slurm_addr_t *addr_ptr;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			ptr = va_arg(ap_copy, void *);
		addr_ptr = ptr;
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _addr2fmt(addr_ptr, substitute_on_stack,
				    substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	case 'd': /* "%pd" -> compact JSON serialized string */
	{
		data_t *d = NULL;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			d = va_arg(ap_copy, void *);
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _print_data_json(d, substitute_on_stack,
					   substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	case 'D': /* "%pD" -> data_type(0xDEADBEEF) */
	{
		data_t *d = NULL;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			d = va_arg(ap_copy, void *);
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _print_data_t(d, substitute_on_stack,
					substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	/*
	 * "%pI" => "JobID=... SLUID=..." on a
	 * slurm_step_id_t
	 */
	case 'I':
	{
		void *ptr = NULL;
		slurm_step_id_t *step_id = NULL;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			ptr = va_arg(ap_copy, void *);
		step_id = ptr;
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  log_build_job_id_str(step_id, substitute_on_stack,
					       substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	case 'J': /* "%pJ" => "JobId=..." */
	{
		void *ptr = NULL;
		job_record_t *job_ptr;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			ptr = va_arg(ap_copy, void *);
		job_ptr = ptr;
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _jobid2fmt(job_ptr, substitute_on_stack,
				     substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	/*
	 * "%ps" => "StepId=... " on a
	 * slurm_step_id_t
	 */
	case 's':
	{
		void *ptr = NULL;
		slurm_step_id_t *step_id = NULL;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			ptr = va_arg(ap_copy, void *);
		step_id = ptr;
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  log_build_step_id_str(step_id, substitute_on_stack,
						substitute_on_stack_bytes,
						STEP_ID_FLAG_PS));
		va_end(ap_copy);
		break;
	}
	/*
	 * "%pS" => "JobId=... StepId=..." on a
	 * step_record_t
	 */
	case 'S':
	{
		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 (int 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;
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _jobid2fmt(job_ptr, substitute_on_stack,
				     substitute_on_stack_bytes));
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _stepid2fmt(step_ptr, substitute_on_stack,
				      substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	/*
	 * "%pu" => "UID=..." on a slurm_msg_t
	 */
	case 'u':
	{
		void *ptr = NULL;
		slurm_msg_auth_t *auth = NULL;
		va_list ap_copy;

		va_copy(ap_copy, ap);
		for (int i = 0; i < *cnt; i++)
			ptr = va_arg(ap_copy, void *);
		auth = ptr;
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
			  _msgauth2fmt(auth, substitute_on_stack,
				       substitute_on_stack_bytes));
		va_end(ap_copy);
		break;
	}
	default:
		/* Unknown */
		break;
	}
}

static void _vxstrfmt_on_our_fmt(const char **fmt_ptr, va_list ap,
				 const char **p_ptr, int *cnt,
				 char **intermediate_fmt_ptr,
				 char **intermediate_pos_ptr)
{
	char *substitute = NULL;
	char substitute_on_stack[256];
	int should_xfree = 1;
	const char *p = *p_ptr;
	const char *fmt = *fmt_ptr;

	/*
	 * p points to the leading % of one of our formats;
	 * append anything from fmt up to p to the intermediate
	 * format string:
	 */
	xstrncatat(*intermediate_fmt_ptr, intermediate_pos_ptr, fmt, p - fmt);
	*fmt_ptr = fmt = p + 1;

	/*
	 * fill the substitute buffer with whatever text we want
	 * to substitute for the format sequence in question:
	 */
	switch (*fmt) {
	case 'p':
		_vxstrfmt_on_our_p_fmt(fmt_ptr, ap, cnt, intermediate_fmt_ptr,
				       intermediate_pos_ptr,
				       substitute_on_stack,
				       sizeof(substitute_on_stack));
		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;
		}
		_set_timestamp(substitute_on_stack,
			       sizeof(substitute_on_stack));
		substitute = substitute_on_stack;
		should_xfree = 0;
		break;
	}
	fmt = (*fmt_ptr += 1);

	if (substitute) {
		char *s = substitute;

		while (*s && (p = *p_ptr = strchr(s, '%'))) {
			/* append up through the '%' */
			xstrncatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
				   s, p - s);
			xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
				  "%%");
			s = ((char *) p) + 1;
		}
		if (*s) {
			/* append whatever's left of the substitution: */
			xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr,
				  s);
		}

		/* deallocate substitute if necessary: */
		if (should_xfree) {
			xfree(substitute);
		}
	}
}

static bool _vxstrfmt_on_fmt(const char **fmt_ptr, va_list ap,
			     const char **p_ptr, int *cnt, bool *is_our_format,
			     bool *found_other_formats,
			     char **intermediate_fmt_ptr,
			     char **intermediate_pos_ptr)
{
	const char *p = *p_ptr;
	const char *fmt = *fmt_ptr;

	/*
	 * 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 'A':
			case 'd':
			case 'D':
			case 'I':
			case 'J':
			case 's':
			case 'S':
			case 'u':
				*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, '%')));

	*p_ptr = p;

	if (*is_our_format) {
		_vxstrfmt_on_our_fmt(fmt_ptr, ap, p_ptr, cnt,
				     intermediate_fmt_ptr,
				     intermediate_pos_ptr);
	} else {
		/*
		 * no more format sequences for us, append the rest of
		 * fmt and exit the loop:
		 */
		xstrcatat(*intermediate_fmt_ptr, intermediate_pos_ptr, fmt);
		return true;
	}

	return false;
}

extern char *vxstrfmt(const char *fmt, va_list ap)
{
	char *intermediate_fmt = NULL, *intermediate_pos = NULL;
	char *out_string = NULL;
	const char *p = NULL;
	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:
			 */
			xstrcatat(intermediate_fmt, &intermediate_pos, fmt);
			break;
		}

		if (_vxstrfmt_on_fmt(&fmt, ap, &p, &cnt, &is_our_format,
				     &found_other_formats, &intermediate_fmt,
				     &intermediate_pos))
			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, bool warn,
		     const char *fmt, va_list args)
{
	char *pfx = "";
	char *buf = NULL;
	char *msgbuf = NULL;
	char *eol = "\n";
	int priority = LOG_INFO;

	/*
	 * Construct the message outside the lock as this can be slow.
	 * The format_print() macro should ensure that we're always going
	 * to print the resulting message through one or more channels.
	 */
	buf = vxstrfmt(fmt, args);

	slurm_mutex_lock(&log_lock);

	if (!LOG_INITIALIZED) {
		log_options_t opts = LOG_OPTS_STDERR_ONLY;
		_log_init(NULL, opts, 0, NULL);
	}

	if (log->opt.raw)
		eol = "\r\n";

	if (SCHED_LOG_INITIALIZED && sched &&
	    (highest_sched_log_level > LOG_LEVEL_QUIET)) {
		xlogfmtcat(&msgbuf, (_have_timefmt() ? "[%M] %s%s" : "%s%s"),
			   sched_log->prefix, pfx);
		_log_printf(sched_log, sched_log->fbuf, sched_log->logfp,
			    "sched: %s%s\n", msgbuf, buf);
		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 = warn ? LOG_WARNING : LOG_INFO;
			pfx = sched ? "sched: " : "";
			pfx = warn ? "warning: " : pfx;
			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 (level <= log->opt.stderr_level) {

		fflush(stdout);
		if (spank) {
			_log_printf(log, log->buf, stderr, "%s%s", buf, eol);
		} else if (running_in_daemon()) {
			if (!_have_timefmt()) {
				_log_printf(log, log->buf, stderr, "%s%s%s",
					    pfx, buf, eol);
			} else {
				xlogfmtcat(&msgbuf, "[%M]");
				_log_printf(log, log->buf, stderr, "%s %s%s%s",
					    msgbuf, pfx, buf, eol);
				xfree(msgbuf);
			}
		} else {
			_log_printf(log, log->buf, stderr, "%s: %s%s%s",
				    log->argv0, pfx, buf, eol);
		}
		fflush(stderr);
	}

	if (!log->logfp || (level > log->opt.logfile_level)) {
		/* do nothing */
	} else if (log->opt.logfile_fmt == LOG_FILE_FMT_JSON) {
		/*
		 * log format json gets all of the logging to match
		 * https://docs.docker.com/config/containers/logging/json-file/
		 */
		char time[50];
		char *json = NULL;
		char *stream;
		data_t *out = data_set_dict(data_new());

		if (level <= log->opt.stderr_level)
			stream = "stderr";
		else
			stream = "stdout";

		log_timestamp(time, sizeof(time));
		data_set_string_fmt(data_key_set(out, "log"), "%s%s%s",
				    log->prefix, pfx, buf);
		data_set_string(data_key_set(out, "stream"), stream);
		data_set_string(data_key_set(out, "time"), time);

		serialize_g_data_to_string(&json, NULL, out, MIME_TYPE_JSON,
					   SER_FLAGS_COMPACT);
		FREE_NULL_DATA(out);

		if (json)
			_log_printf(log, log->fbuf, log->logfp, "%s\n", json);

		xfree(json);
		fflush(log->logfp);
	} else {
		xassert(log->opt.logfile_fmt == LOG_FILE_FMT_TIMESTAMP);
		xlogfmtcat(&msgbuf, (_have_timefmt() ? "[%M] %s%s" : "%s%s"),
			   log->prefix, pfx);
		_log_printf(log, log->fbuf, log->logfp, "%s%s\n", msgbuf, buf);
		fflush(log->logfp);

		xfree(msgbuf);
	}

	if (level <=  log->opt.syslog_level) {

		/* Avoid changing errno if syslog fails */
		int orig_errno = errno;
		syslog(priority, "%s%s%s", log->prefix, pfx, buf);
		errno = orig_errno;
	}

	slurm_mutex_unlock(&log_lock);

	xfree(buf);
}

extern bool log_has_data(void)
{
	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);
}

extern void log_flush(void)
{
	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();

	if (getenv("ABORT_ON_FATAL"))
		abort();

	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, false, fmt, ap);
	va_end(ap);
}

void warning(const char *fmt, ...)
{
	va_list ap;
	va_start(ap, fmt);
	_log_msg(LOG_LEVEL_INFO, false, false, true, fmt, ap);
	va_end(ap);
}

void slurm_info(const char *fmt, ...)
{
	LOG_MACRO(LOG_LEVEL_INFO, false, fmt);
}

void slurm_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);
}

void sched_error(const char *fmt, ...)
{
	LOG_MACRO(LOG_LEVEL_ERROR, true, fmt);
}

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);
}

extern char *log_build_job_id_str(slurm_step_id_t *step_id, char *buf,
				  int buf_size)
{
	xassert(buf);
	xassert(buf_size > 1);

	buf[0] = '\0';

	if (!step_id) {
		snprintf(buf, buf_size, "%%.0sJobId=Invalid SLUID=Invalid");
	} else if (step_id->job_id && (step_id->job_id != NO_VAL) &&
		   !step_id->sluid) {
		snprintf(buf, buf_size, "%%.0sJobId=%u", step_id->job_id);
	} else if (step_id->job_id && (step_id->job_id != NO_VAL)) {
		int pos = snprintf(buf, buf_size,
				   "%%.0sJobId=%u SLUID=", step_id->job_id);
		if (pos > 0)
			print_sluid(step_id->sluid, buf + pos, buf_size - pos);
	} else if (step_id->sluid) {
		int pos = snprintf(buf, buf_size, "%%.0sSLUID=");
		if (pos > 0)
			print_sluid(step_id->sluid, buf + pos, buf_size - pos);
	} else {
		snprintf(buf, buf_size, "%%.0sJobId=Invalid SLUID=Invalid");
	}

	return buf;
}

/*
 * log_build_step_id_str() - print a slurm_step_id_t as " StepId=...", with
 * Batch and Extern used as appropriate.
 */
extern char *log_build_step_id_str(
	slurm_step_id_t *step_id, char *buf, int buf_size, uint16_t flags)
{
	int pos = 0;

	xassert(buf);
	xassert(buf_size > 1);

	buf[pos] = '\0';

	if (flags & STEP_ID_FLAG_SPACE)
		buf[pos++] = ' ';

	/*
	 * NOTE: You will notice we put a %.0s in front of the string if running
	 * with %ps like interactions.
	 * This is to handle the fact that we can't remove the step_id
	 * argument from the va_list directly. So when we call vsnprintf()
	 * to handle the va_list this will effectively skip this argument.
	 */
	if (flags & STEP_ID_FLAG_PS)
		pos += snprintf(buf + pos, buf_size - pos, "%%.0s");

	if (!(flags & STEP_ID_FLAG_NO_PREFIX))
		pos += snprintf(buf + pos, buf_size - pos, "%s",
				(!step_id || (step_id->step_id != NO_VAL)) ?
				"StepId=" : "JobId=");

	if (!step_id || (!step_id->job_id && !step_id->sluid)) {
		snprintf(buf + pos, buf_size - pos, "Invalid");
		return buf;
	}

	/* If we want to prefix the job id or sluid. */
	if (!(flags & STEP_ID_FLAG_NO_JOB)) {
		if (step_id->job_id && step_id->job_id != NO_VAL) {
			pos += snprintf(buf + pos, buf_size - pos, "%u%s",
					step_id->job_id,
					step_id->step_id == NO_VAL ? "" : ".");
		} else if (step_id->sluid) {
			char tmpstr[SLUID_STR_BYTES];
			print_sluid(step_id->sluid, tmpstr, sizeof(tmpstr));
			pos += snprintf(buf + pos, buf_size - pos, "%s%s",
					tmpstr,
					step_id->step_id == NO_VAL ? "" : ".");
		}
	}

	if ((pos >= buf_size) || (step_id->step_id == NO_VAL))
		return buf;

	if (step_id->step_id == SLURM_BATCH_SCRIPT)
		pos += snprintf(buf + pos, buf_size - pos, "batch");
	else if (step_id->step_id == SLURM_EXTERN_CONT)
		pos += snprintf(buf + pos, buf_size - pos, "extern");
	else if (step_id->step_id == SLURM_INTERACTIVE_STEP)
		pos += snprintf(buf + pos, buf_size - pos, "interactive");
	else if (step_id->step_id == SLURM_PENDING_STEP)
		pos += snprintf(buf + pos, buf_size - pos, "TBD");
	else
		pos += snprintf(buf + pos, buf_size - pos, "%u",
				step_id->step_id);

	if (pos >= buf_size)
		return buf;

	if (!step_id->sluid && (step_id->step_het_comp != NO_VAL))
		snprintf(buf + pos, buf_size - pos, "+%u",
			 step_id->step_het_comp);

	return buf;
}

extern void slurm_log_flag_hex(const void *data, size_t len, ssize_t start,
			       ssize_t end, const char *fmt, ...)
{
	va_list ap;
	char *prepend;
	static const int hex_cols = 16;

	if (!data || !len)
		return;

	if (start < 0)
		start = 0;
	if ((end < 0) || (end > len))
		end = len;

	va_start(ap, fmt);
	prepend = vxstrfmt(fmt, ap);
	va_end(ap);

	for (size_t i = start; (i < end); ) {
		int remain = end - i;
		int print = (remain < hex_cols) ? remain : hex_cols;
		char *phex = xstring_bytes2hex((data + i), print, " ");
		char *pstr = xstring_bytes2printable((data + i), print, '.');

		format_print(LOG_LEVEL_VERBOSE, "%s [%04zu/%04zu] 0x%s \"%s\"",
			     prepend, i, len, phex, pstr);

		i += print;
		xfree(phex);
		xfree(pstr);
	}

	xfree(prepend);
}

log_closeall_skip_t log_closeall_pre(void)
{
	log_closeall_skip_t skip = {
		.log_fd = -1,
		.sched_log_fd = -1,
	};

	slurm_mutex_lock(&log_lock);

	if (log && log->logfp)
		skip.log_fd = fileno(log->logfp);
	else
		skip.log_fd = fileno(stderr);

	if (sched_log && sched_log->logfp)
		skip.sched_log_fd = fileno(sched_log->logfp);

	closelog();
	syslog_open = false;

	slurm_mutex_unlock(&log_lock);

	return skip;
}

void log_closeall_post(void)
{
	slurm_mutex_lock(&log_lock);

	/*
	 * Re-open syslog file descriptor after closeall() with same settings
	 * if logging had already been initialized.
	 */
	if (log && log->initialized) {
		openlog(log->argv0, LOG_PID, log->facility);
		syslog_open = true;
	}

	slurm_mutex_unlock(&log_lock);
}