Project

General

Profile

Download (30.6 KB) Statistics
| Branch: | Tag: | Revision:

root/software/fss-parallel-tools/common/spew.c @ a1fcfb60

#ifndef _GNU_SOURCE
#define _GNU_SOURCE // for pthread_getname_np(), sync_file_range()
#endif // !_GNU_SOURCE

#include "spew.h"
#include <errno.h> // for errno, EEXIST
#include <fcntl.h> // for sync_file_range()
#include <execinfo.h> // for backtrace, backtrace_symbols
#include <pthread.h> // for pthread_mutex_lock, pthread_mutex_unlock
#include <stdarg.h> // for va_list, va_end, va_start
#include <stddef.h> // for size_t, NULL, ptrdiff_t
#include <stdint.h> // for uint64_t
#include <stdio.h> // for fprintf, stderr, FILE, fputs, vsnprintf
#include <stdlib.h> // for abort, free
#include <string.h> // for strnlen, strcmp, strncpy
#include <sys/stat.h> // for stat, mkdir, S_IRWXG, S_IRWXO, S_IRWXU
#include <sys/time.h> // for CLOCK_REALTIME
#include <time.h> // for tm, timespec, gmtime_r, clock_gettime
#include <unistd.h> // for getpid
#include "backtrace.h" // for spew_backtrace
#include "tsan.h" // for NO_SANITIZE_THREAD
#include "../version.h" // for GITREV
#include "debug-tag.h" // for debt_snprintf
#include "simplest-defs.h" // for NELEM, STRINGIFY, boolint, STATIC_ASSERT
#include "sparse.h" // for __force
#include "error.h"
#include <sys/syscall.h>


#if defined(ASSERT) || defined(CHECK)
#error CANNOT_USE_ASSERT_OR_CHECK_IN_THIS_FILE
#endif

struct spewlog {
// Everything in this struct is protected by this mutex.
//
pthread_mutex_t mutex;

// Settings / flags.
//
size_t spew_level;
boolint suppress_spewage;
// Logs live in <logrootdir>/<lfname_root>/
// <lfname_root>--<rollpd>m--YY-mm-ddTHH-MM-00Z.log.
//
char logrootdir[512];
char lfname_root[512];
// One of: 1, 10, 60, 1440 (== 1, 10 minutes; 1, 24 hrs).
// A new roll period starts at midnight.
//
size_t roll_period_minutes;
boolint spew_to_stderr;
// Name and FILE* for file currently being spewed to.
//
// NOTE: This field is a sentinel whose existence serves to
// convince maybe_roll_logfile() not to continuously try to reopen
// a logfile in e.g. disk-full conditions.
//
char lfname[1024];
FILE *logfile;
};

// Errors in the spew package can't call spew. By means of calling
// this method, spew-package error spewage goes to the logfile (if
// it's open), else stderr (which will fail if the process has already
// shut stderr, but in that case, there's nothing to do).
//
// This method may be called when log->mutex is not held -- from
// signal-handlers, for example.
//
static FILE *
spew_logfile(struct spewlog *log)
{
FILE *logfile = log->logfile;
return logfile != NULL ? logfile : stderr;
}

static void
spew_backtrace_simple_internal(FILE *f)
{
void *trace[32];
int n = backtrace(trace, (__force int)NELEM(trace));

if (n > 0) {
char **symbols = backtrace_symbols(trace, n);

if (symbols) {
fprintf(f, "BACKTRACE:\n");
for (size_t i = 0;
i < /*size_t_of_ptrdiff_t*/(__force size_t)(n);
i++) {
fprintf(f, " [%zu] %s\n", i, symbols[i]);
}

free(symbols);

} else {
perror("backtrace_symbols()");
}

} else {
perror("backtrace()");
}
}

void
spew_backtrace_simple(void)
{
spew_backtrace_simple_internal(spew_logfile(&the_spew_log));
}

static void spew_backtrace_simple_and_abort(FILE *f)
__attribute__ ((__noreturn__));
static void
spew_backtrace_simple_and_abort(FILE *f)
{
spew_backtrace_simple_internal(f);
abort();
}


///////////////////////////////////////////////////////////////////////////
// Assertions in the spew package, which must not call log0()
// so as to avoid infinite recursion.
#define SPEW_CHECK(x) \
((x) ? (void) (0) : \
spew_assert_fail(STRINGIFY(x), __FILE__, __LINE__, __PRETTY_FUNCTION__))
#define SPEW_ASSERT SPEW_CHECK

static void
spew_assert_fail(const char *assertion,
const char *file, size_t line, const char *function)
{
FILE *f = spew_logfile(&the_spew_log);
fprintf(f, "FATAL: SPEW_ASSERTION_FAILURE: %s:%s:%s:%zu\n",
assertion, file, function, line);
spew_backtrace_simple_and_abort(f);
}


///////////////////////////////////////////////////////////////////////////
// spew_level stuff
//

static const char *spew_level_name[] = {
[SPEW_TRACE] = "TRACE",
[SPEW_DEBUG] = "DEBUG",
[SPEW_INFO] = "INFO",
[SPEW_TEST_INFO] = "TINFO",
[SPEW_WARN] = "WARN",
[SPEW_ERROR] = "ERROR",
[SPEW_BUG] = "BUG",
[SPEW_FATAL] = "FATAL",
[SPEW_CRIT] = "CRIT",
};

const char *
log_get_level_name(size_t level)
{
SPEW_ASSERT(level < NELEM(spew_level_name));
return spew_level_name[level];
}

size_t
log_level_of_level_name(const char *level_name)
{
for (size_t level = FIRST_SPEW_LEVEL; level < N_SPEW_LEVELS; ++level) {
if (strcmp(level_name, spew_level_name[level]) == 0) {
return level;
}
}
fprintf(stderr, "FATAL: log_level_of_level_name(): "
"unrecognized level_name: '%s'\n", level_name);
spew_backtrace_simple_and_abort(stderr);
}

static void
log_spew_level_change(size_t spew_level, size_t old_level, size_t new_level)
{
SPEW_ASSERT(old_level < NELEM(spew_level_name));
SPEW_ASSERT(new_level < NELEM(spew_level_name));
spew(spew_level, "spew level change: %s -> %s",
spew_level_name[old_level],
spew_level_name[new_level]);
}

size_t
log_set_level(struct spewlog *log, size_t new_level)
{
SPEW_ASSERT(new_level < N_SPEW_LEVELS);

// Spew the level change at the lower of the two levels; accomplished by
// spewing before the change if new > old, else after.
//
size_t old_level;
pthread_mutex_lock(&log->mutex); {
old_level = log->spew_level;
} pthread_mutex_unlock(&log->mutex);
if (new_level > old_level) {
log_spew_level_change(old_level, old_level, new_level);
}
pthread_mutex_lock(&log->mutex); {
old_level = log->spew_level;
log->spew_level = new_level;
} pthread_mutex_unlock(&log->mutex);
if (new_level <= old_level) {
log_spew_level_change(new_level, old_level, new_level);
}

return old_level;
}

/* spew_level += (add - sub), unsigned */
size_t
log_add_level(struct spewlog *log, size_t add, size_t sub)
{
SPEW_ASSERT(add == 0 || sub == 0); /* normal form */
size_t level;

/* This update is not atomic. There is no point in making it atomic
because log_set_level() is not atomic either. */
pthread_mutex_lock(&log->mutex); {
level = log->spew_level;
} pthread_mutex_unlock(&log->mutex);

level = (level + add >= N_SPEW_LEVELS)
? N_SPEW_LEVELS - 1
: level + add;
level = (level >= sub)
? level - sub
: FIRST_SPEW_LEVEL;
return log_set_level(log, level);
}

static pthread_mutex_t spew_level_lock =
PTHREAD_ERRORCHECK_MUTEX_INITIALIZER_NP;
static uint64_t spew_level_counts[NELEM(spew_level_name)];

void
HACK_log_inc_level_count(size_t level)
{
SPEW_ASSERT(level < NELEM(spew_level_counts));

pthread_mutex_lock(&spew_level_lock); {
spew_level_counts[level]++;
} pthread_mutex_unlock(&spew_level_lock);
}

void
spew_reset_level_counts(uint64_t *level_counters,
size_t level_counters_len)
{
SPEW_ASSERT(level_counters_len == NELEM(spew_level_counts));
pthread_mutex_lock(&spew_level_lock); {
for (size_t level = 0; level < NELEM(spew_level_counts); ++level) {
level_counters[level] = spew_level_counts[level];
spew_level_counts[level] = 0;
}
} pthread_mutex_unlock(&spew_level_lock);
}


///////////////////////////////////////////////////////////////////////////
// logfile stuff
//

// struct spewlog contains arrays with too many elements to initialize
// explicitly, so don't let sparse in on the secret.
//
struct spewlog the_spew_log
#ifndef __CHECKER__
= {
.mutex = PTHREAD_MUTEX_INITIALIZER,
.spew_level = SPEW_TEST_INFO,
.roll_period_minutes = SPEW_DEFAULT_ROLL_PERIOD,
.spew_to_stderr = 1,
}
#endif
;
struct spewlog the_metrics_log
#ifndef __CHECKER__
= {
.mutex = PTHREAD_MUTEX_INITIALIZER,
.roll_period_minutes = SPEW_DEFAULT_ROLL_PERIOD,
.spew_to_stderr = 1,
}
#endif
;

static void
log_xstrncpy(char *dest, const char *src, size_t n)
{
size_t len = strnlen(src, n);
SPEW_ASSERT(len < n);
// gcc 8.1 with -Werror=stringop-truncation doesn't like n as the argument
// to strncpy() since it figures out that n is exactly the size of dest.
strncpy(dest, src, n-1);
dest[len] = 0;
}

static void
log_xbasename(char *dest, size_t dest_len, const char *path)
{
// Copy path because some versions of basename() can modify their
// argument.
//
char path_copy[512];
log_xstrncpy(path_copy, path, NELEM(path_copy));
char *bn = basename(path_copy);
log_xstrncpy(dest, bn, dest_len);
}

static int
log_xsnprintf(char *str, size_t size, const char *format, ...)
__attribute__((format(printf, 3, 4)));
static int
log_xsnprintf(char *str, size_t size, const char *format, ...)
{
SPEW_ASSERT(str);
SPEW_ASSERT(format);

va_list args;
#ifndef __CHECKER__
// va_start() contains a cast to void * (from char const **, in
// this case), which runs afoul of sparse's check for qualifier
// drops.
//
va_start(args, format);
#endif // !__CHECKER__
int size_otherwise = vsnprintf(str, size, format, args);
va_end(args);
SPEW_ASSERT(0 <= size_otherwise &&
(__force size_t)(ptrdiff_t)size_otherwise < size);
return size_otherwise;
}

static size_t
log_snprintf(char *str, size_t size, const char *format, ...)
__attribute__((format(printf, 3, 4)));
static size_t
log_snprintf(char *str, size_t size, const char *format, ...)
{
va_list args;
#ifndef __CHECKER__
// va_start() contains a cast to void * (from char const **, in
// this case), which runs afoul of sparse's check for qualifier
// drops.
//
va_start(args, format);
#endif // !__CHECKER__
int size_otherwise = vsnprintf(str, size, format, args);
va_end (args);
SPEW_ASSERT(size_otherwise >= 0);
size_t so_pos = /*__force_size_t*/(__force size_t)(size_otherwise);
return (so_pos > size) ? size : so_pos;
}

static size_t
log_vsnprintf(char *str, size_t size, const char *format, va_list args)
__attribute__((format(printf, 3, 0)));
static size_t
log_vsnprintf(char *str, size_t size, const char *format, va_list args)
{
int size_otherwise = vsnprintf(str, size, format, args);
SPEW_ASSERT(size_otherwise >= 0);
size_t so_pos = /*__force_size_t*/(__force size_t)(size_otherwise);
return (so_pos > size) ? size : so_pos;
}

static void
log_snprintf_logfile_tstr(char *tstr, size_t tstr_len,
const struct timespec *now)
{
struct tm tm;
gmtime_r(&now->tv_sec, &tm);

size_t len = strftime(tstr, tstr_len, "%Y-%m-%dT%H-%M-%S", &tm);
SPEW_ASSERT(len > 0);
}

static void
log_snprintf_lfdir(struct spewlog *log, char *b, size_t b_len)
{
log_xsnprintf(b, b_len, "%s/%s", log->logrootdir, log->lfname_root);
}

static void
log_snprintf_lfname(struct spewlog *log, char *b, size_t b_len,
boolint include_sec_since_midnight_tag,
const struct timespec *now)
{
struct tm tm;
gmtime_r(&now->tv_sec, &tm);

// Construct "seconds since midnight" tag if needed.
// Note that it is necessary to do this before modifying tm.
//
char ssm_tag[16];
if (include_sec_since_midnight_tag) {
int sec_since_midnight =
((tm.tm_hour * 60) + tm.tm_min) * 60 + tm.tm_sec;
log_xsnprintf(ssm_tag, NELEM(ssm_tag), "%d.", sec_since_midnight);
} else {
ssm_tag[0] = '\0';
}

switch (log->roll_period_minutes) {
case 1440:
tm.tm_hour = 0;
/* fallthrough */ /* Make gcc7 happy with -Wimplicit-fallthrough */
case 60:
tm.tm_min = 0;
/* fallthrough */
case 10:
tm.tm_min = (tm.tm_min / 10) * 10;
case 1:
break;
default: {
FILE *f = spew_logfile(log);
fprintf(f, "FATAL: log_snprintf_lfname(): "
"unexpected log->roll_period_minutes=%zd\n",
log->roll_period_minutes);
spew_backtrace_simple_and_abort(f);
}}

char lfdir[256];
log_snprintf_lfdir(log, lfdir, NELEM(lfdir));

log_xsnprintf(b, b_len,
"%s/%s--%zdm--%04d-%02d-%02dT%02d-%02d-00Z.%slog",
lfdir, log->lfname_root, log->roll_period_minutes,
tm.tm_year+1900, tm.tm_mon+1, tm.tm_mday,
tm.tm_hour, tm.tm_min, ssm_tag);
}

static void log_maybe_close_logfile(struct spewlog *log);

/*
* Format and output a log line to the log file.
*/
static void
log_one_line(struct spewlog *log, size_t level,
const struct timespec *now, char const * function,
char const * filename, size_t line, char const * out_string)
{
char l[1024];
size_t li = 0;

char now_str[64];
log_snprintf_logfile_tstr(now_str, NELEM(now_str), now);

char threadname[THREADNAME_SIZE];
int ret =
pthread_getname_np(pthread_self(), threadname, sizeof(threadname));
if (ret != 0) {
// If we cannot get the thread name just set it to <noname>
strncpy(threadname, "<noname>", NELEM(threadname));
}

char debt_buf[64];
debt_snprintf(&debt_buf[0], sizeof(debt_buf));

char file_basename[512];
log_xbasename(file_basename, NELEM(file_basename), filename);

li += log_snprintf(l+li, NELEM(l)-li,
"%s.%06ldZ %d:%ld:%5s:%s:%s%s:%s:%zd: %s\n",
now_str, now->tv_nsec/1000, getpid(),
syscall(SYS_gettid), spew_level_name[level],
threadname, debt_buf, function, file_basename, line,
out_string);

// Ensure that truncated log lines are newline-terminated.
STATIC_ASSERT(NELEM(l) > 2);
l[NELEM(l)-2] = '\n';
l[NELEM(l)-1] = '\0';

// If logging has not been configured yet, spew to stderr. Once logging
// has been configured, when something goes wrong, logging gets diverted
// to stderr. When that is the case, only spew SPEW_ERROR and higher.
boolint early = (strnlen(log->lfname_root, NELEM(log->lfname_root)) == 0);
boolint spew_failed = !!0;
if (early || log->logfile != stderr || level >= SPEW_ERROR) {
spew_failed = fputs(l, log->logfile) == EOF; // EOF == any error.
}

if (spew_failed || fflush(log->logfile) == EOF) {
fprintf(stderr, "ERROR: Write to '%s' failed (%s(%d)) -- "
"is filesystem full?\n",
log->lfname, xstrerror(errno), errno);
fprintf(stderr, "ERROR: all spewage now going to stderr\n");
log_maybe_close_logfile(log);
log->logfile = stderr;
}

if (log->logfile != stderr) {
int logfile_fd = fileno(log->logfile);
struct stat statbuf;
if (fstat(logfile_fd, &statbuf) != 0) {
fprintf(stderr, "ERROR: fstat('%s') failed (%s(%d))\n",
log->lfname, xstrerror(errno), errno);
} else if (sync_file_range(
logfile_fd,
0, statbuf.st_size & ~(statbuf.st_blksize-1),
SYNC_FILE_RANGE_WRITE
) != 0) {
fprintf(stderr, "ERROR: sync_file_range('%s') failed (%s(%d))\n",
log->lfname, xstrerror(errno), errno);
}
}

// BUG and higher always goes to stderr as well.
if (1
&& (log->spew_to_stderr || level >= SPEW_BUG)
&& spew_logfile(log) != stderr) {
fputs(l, stderr);
}
}

/**
* Behaves like 'mkdir -p'.
* Copied (approximately) from util.c.
* If {,NON_}LEAF_MODE is 0, use rwxrwxrwx.
*/
static void
mkdir_p(const char *path, size_t path_len, mode_t leaf_mode, mode_t non_leaf_mode)
{
char prefix[1024];
size_t len = strnlen(path, path_len);
SPEW_ASSERT(len < NELEM(prefix));

mode_t rwxrwxrwx = (__force mode_t)(S_IRWXU|S_IRWXG|S_IRWXO);
if (leaf_mode == 0) {
leaf_mode = rwxrwxrwx;
}
if (non_leaf_mode == 0) {
non_leaf_mode = rwxrwxrwx;
}

// For each successively larger prefix of pathname components (separated
// by '/' characters), if a directory of that name doesn't exist of that
// name, create it.
for (size_t i = 0; i < len + 1; i++) {
if (0
|| i == len
|| (i > 0 && path[i] == '/')) {

prefix[i] = 0;

struct stat s;
if (stat(prefix, &s) == 0) {
// Directory exists.
SPEW_CHECK(S_ISDIR(s.st_mode));
} else {
// Directory doesn't exist. Create it and set its mode bits.

// Use leaf_mode when last/component or last/component/.
mode_t mode = i == len || (i == len-1 && path[i] == '/') ? leaf_mode : non_leaf_mode;
// Don't call spew() here (for obvious reasons).
fprintf(stderr, "INFO: mkdir(%s)\n", prefix);
int err = mkdir(prefix, mode);
if (err != 0 && err != EEXIST) {
// Skip EEXIST error -- this can happen in a race.
fprintf(stderr, "ERROR: mkdir(): errno = %s(%d)\n",
xstrerror(errno), errno);
} else {
// Call chmod() explicitly because mkdir() is modified by
// umask.
err = chmod(prefix, mode);
if (err != 0) {
fprintf(stderr, "ERROR: chmod(): errno = %s(%d)\n",
xstrerror(errno), errno);
}
}
}
}

prefix[i] = path[i];
}
}

static void
log_maybe_close_logfile(struct spewlog *log)
{
if (log->logfile != NULL && log->logfile != stderr) {
if (fsync(fileno(log->logfile)) != 0) {
fprintf(stderr, "ERROR: syncfs(\"%s\") failed: %s(%d)\n",
log->lfname, xstrerror(errno), errno);
}
if (fclose(log->logfile) != 0) {
fprintf(stderr, "ERROR: fclose(\"%s\") failed: %s(%d)\n",
log->lfname, xstrerror(errno), errno);
}
log->logfile = NULL;
//
// NOTE: Don't clear log->lfname here -- see comment for
// spewlog.lfname in structure declaration.
}
}

void
log_config(struct spewlog *log, const char *logrootdir, const char *argv0,
size_t roll_period_m, boolint spew_to_stderr, boolint debug)
{
// Ensure that spew_logfile() doesn't read garbage (it might be
// called by things we call).
//
log_maybe_close_logfile(log);
log->logfile = NULL;

pthread_mutex_lock(&log->mutex); {
log_xstrncpy(log->logrootdir, logrootdir, NELEM(log->logrootdir));
log_xbasename(log->lfname_root, NELEM(log->lfname_root), argv0);

if (1
&& roll_period_m != 1
&& roll_period_m != 10
&& roll_period_m != 60
&& roll_period_m != 1440) {
fprintf(stderr,
"ERROR: unhandled roll_period_m: %zd; "
"using default (%d minutes)\n",
roll_period_m, SPEW_DEFAULT_ROLL_PERIOD);
roll_period_m = SPEW_DEFAULT_ROLL_PERIOD;
}
log->roll_period_minutes = roll_period_m;
log->spew_to_stderr = spew_to_stderr;
} pthread_mutex_unlock(&log->mutex);

char lfdir[256];
log_snprintf_lfdir(log, lfdir, NELEM(lfdir));
mkdir_p(lfdir, NELEM(lfdir),
/*default leaf_mode: rwxrwxrwx*/0, /*default non_leaf_mode: rwxrwxrwx*/0);

// HACK [dann 2017-02-13]: When configuring the non-metrics log,
// also configure the metrics log for this process -- use the same
// parameters for the metrics log but a different
// log-directory/logfile-name, and set the level differently as
// well.
//
if (log == &the_metrics_log) {
log_set_level(log, 0);
} else {
if (debug) {
log_set_level(log, SPEW_DEBUG);
} else {
log_set_level(log, SPEW_INFO);
}

char new_argv0[256];
log_xsnprintf(new_argv0, NELEM(new_argv0), "%s-mlog", argv0);
log_config(&the_metrics_log, logrootdir, new_argv0, roll_period_m,
/*spew_to_stderr=*/!!0, /*debug=*/!!0);
}

}

void
log_teardown(struct spewlog *log)
{
pthread_mutex_lock(&log->mutex); {
log_maybe_close_logfile(log);
log->logrootdir[0] = '\0';
log->lfname_root[0] = '\0';
} pthread_mutex_unlock(&log->mutex);
}

static /*reopen*/boolint
rename_logfile_if_too_large(struct spewlog *log, const struct timespec *now)
{
SPEW_ASSERT(log->lfname[0] != '\0');

struct stat s;
if (0
|| log->logfile == NULL
|| log->logfile == stderr
|| stat(log->lfname, &s) != 0)
{
// Don't rename logfile if not spewing to it or if we can't
// stat it (for whatever reason).
//
return 0;
}

if (s.st_size > SPEW_MAX_LOGFILE_SIZE) {
char alt_lfname[NELEM(log->lfname)];
log_snprintf_lfname(log, alt_lfname, NELEM(alt_lfname),
/*include_sec_since_midnight_tag=*/!0, now);
fprintf(stderr, "renaming '%s' ==> '%s'\n", log->lfname, alt_lfname);
if (rename(log->lfname, alt_lfname) == 0) {
// Ensure that roll_logfile will reopen a new logfile,
// now that the old one has been moved out of the way.
//
log->lfname[0] = '\0';
return !0;
}
fprintf(stderr, "ERROR: rename('%s' ==> '%s') failed: %s(%d)\n",
log->lfname, alt_lfname, xstrerror(errno), errno);
log_maybe_close_logfile(log);
log->logfile = stderr;
fprintf(stderr, "ERROR: all spewage now going to stderr\n");
}
return 0;
}

// Open a new logfile, or close the currently-open file and open a new
// one if it's time to roll, or if the current logfile is too large
// for lumberjack's liking. If the open fails, or if log_config() has
// not been called yet, use stderr.
//
static void
maybe_roll_logfile(struct spewlog *log, const struct timespec *now)
{
// Don't try to open if spew_config() hasn't been called yet.
//
if (strnlen(log->lfname_root, NELEM(log->lfname_root)) == 0) {
log->logfile = stderr;
return;
}

char desired_lfname[256];
log_snprintf_lfname(log, desired_lfname, NELEM(desired_lfname),
/*include_sec_since_midnight_tag=*/0, now);
boolint should_roll = 0
|| strcmp(desired_lfname, log->lfname) != 0
|| rename_logfile_if_too_large(log, now);

if (should_roll) {
log_maybe_close_logfile(log);
SPEW_ASSERT(log->logfile == NULL || log->logfile == stderr);
}

if (log->logfile == NULL || (log->logfile == stderr && should_roll)) {
SPEW_ASSERT(strnlen(desired_lfname, NELEM(desired_lfname)) <
NELEM(log->lfname));
log_xstrncpy(log->lfname, desired_lfname, NELEM(log->lfname)-1);
log->logfile = fopen(desired_lfname, "ae");
if (log->logfile == NULL) {
fprintf(stderr, "ERROR: failed to open '%s' (%s(%d))\n",
desired_lfname, xstrerror(errno), errno);
fprintf(stderr, "ERROR: all spewage now going to stderr\n");
log->logfile = stderr;
} else {
/* Logfile rolled. Set the first line to the gitrev */
if (log != &the_metrics_log) {
log_one_line(log, SPEW_INFO, now, __FUNCTION__,
__FILE__, (size_t)__LINE__, gitrev);
}
}
}

SPEW_ASSERT(log->logfile != NULL);

/* set LOGFILE to be line-buffered */
setvbuf(log->logfile, NULL, _IOLBF, 0);
}


///////////////////////////////////////////////////////////////////////////
// spew() routines.
//

// Helper routine for log{0,1}().
//
static void
log_gettime_or_abort(struct spewlog *log, struct timespec *now)
{
if (clock_gettime(CLOCK_REALTIME, now) != 0) {
FILE *f = spew_logfile(log);
fprintf(f,
"FATAL: clock_gettime() failed: %s(%d)\n",
xstrerror(errno), errno);
spew_backtrace_simple_and_abort(f);
}
}

boolint
log_enabled(struct spewlog *log, size_t level)
NO_SANITIZE_THREAD /* we don't acquire the lock to read log->spew_level.
Not worth it. */

{
return (level >= log->spew_level);
}

// logv() is the main mechanism for writing to an application log file.
//
// DO NOT CALL CHECK()/ASSERT() FROM THIS FUNCTION OR ANYTHING IT
// CALLS OR ELSE SUFFER INFINITE RECURSION !!!
//
void
logv(struct spewlog *log,
boolint honor_spewage_suppression,
boolint maybe_roll,
boolint is_stack_trace,
size_t level,
const char *file,
size_t line,
const char *fn,
const char *fmt,
va_list ap)
{
if (level < log->spew_level) {
return;
}

HACK_log_inc_level_count(level);
boolint did_spew;

pthread_mutex_lock(&log->mutex); {

if (honor_spewage_suppression && log->suppress_spewage) {
// Suppress spewage.
did_spew = 0;
} else {
struct timespec now;
log_gettime_or_abort(log, &now);
if (maybe_roll || log->logfile == NULL) {
maybe_roll_logfile(log, &now);
}

char l[1024];
size_t ls = NELEM(l);
log_vsnprintf(l, ls, fmt, ap);
l[ls-1] = '\0';

log_one_line(log, level, &now, fn, file, line, l);
did_spew = 1;
}

} pthread_mutex_unlock(&log->mutex);

// Add backtrace to BUG spewage (which is not fatal, so we we wouldn't
// otherwise see a backtrace).
if (did_spew && level == SPEW_BUG && !is_stack_trace) {
spew_backtrace(SPEW_BUG);
}
}


// log0(), wrapped by spew() in util.h, is the main mechanism for
// writing to an application log file.
//
// DO NOT CALL CHECK()/ASSERT() FROM THIS FUNCTION OR ANYTHING IT
// CALLS OR ELSE SUFFER INFINITE RECURSION !!!
//
void
log0(struct spewlog *log,
boolint honor_spewage_suppression,
boolint maybe_roll,
boolint is_stack_trace,
size_t level,
const char *file,
size_t line,
const char *fn,
const char *fmt,
...)
{
va_list ap;
#ifndef __CHECKER__
// va_start() contains a cast to void * (from char const **, in this
// case), which runs afoul of sparse's check for qualifier drops.
//
va_start(ap, fmt);
#endif // !__CHECKER__
logv(log, honor_spewage_suppression, maybe_roll, is_stack_trace,
level, file, line, fn, fmt, ap);
va_end(ap);
}

void
log1(struct spewlog *log,
const char *fmt,
...)
{
SPEW_ASSERT(log->spew_level == 0); // UNUSED

va_list ap;

pthread_mutex_lock(&log->mutex); {

struct timespec now;
log_gettime_or_abort(log, &now);
maybe_roll_logfile(log, &now);

if (log->logfile != stderr) {
char now_str[64];
log_snprintf_logfile_tstr(now_str, NELEM(now_str), &now);

char l[1024];
size_t ls = NELEM(l);
size_t li = 0;

li += log_snprintf(l+li, ls-li,
"%s.%06ldZ: ", now_str, now.tv_nsec/1000);

#ifndef __CHECKER__
// va_start() contains a cast to void * (from char const **,
// in this case), which runs afoul of sparse's check for
// qualifier drops.
//
va_start(ap, fmt);
#endif // !__CHECKER__
li += log_vsnprintf(l+li, ls-li, fmt, ap);
va_end(ap);
li += log_snprintf(l+li, ls-li, "\n");

// Ensure that truncated log lines are newline-terminated.
//
l[ls-2] = '\n';
l[ls-1] = '\0';

if (fputs(l, log->logfile) == EOF) { // EOF == any error.
fprintf(stderr, "ERROR: Write to '%s' failed (%s(%d)) -- "
"is filesystem full?\n",
log->lfname, xstrerror(errno), errno);
log_maybe_close_logfile(log);
log->logfile = stderr;
fprintf(stderr, "ERROR: no longer spewing metrics to %s\n",
log->lfname);
}
}
} pthread_mutex_unlock(&log->mutex);
}

boolint
spew_logfile_ok(struct spewlog *log)
{
boolint ok;
pthread_mutex_lock(&log->mutex); {
struct timespec now;
log_gettime_or_abort(log, &now);
maybe_roll_logfile(log, &now);
ok = (log->logfile != stderr);
} pthread_mutex_unlock(&log->mutex);
return ok;
}

void
spew_config(int argc, char *const argv[], const char *logrootdir,
size_t roll_period_m, boolint spew_to_stderr, boolint debug)
{
SPEW_ASSERT(argc > 0);
log_config(&the_spew_log, logrootdir, argv[0],
roll_period_m, spew_to_stderr, debug);
spew(SPEW_INFO, "============= STARTING =============");
spew(SPEW_INFO, "GITREV = %s", gitrev);
spew(SPEW_INFO, "ARGV = [");
for (size_t i = 0; i < (__force size_t)argc; i++) {
spew(SPEW_INFO, " \"%s\",", argv[i]);
}
spew(SPEW_INFO, "log directory: %s", logrootdir);
spew(SPEW_INFO, "]");
}

void
spew_teardown(void)
{
spew(SPEW_INFO, "goodbye");
log_teardown(&the_spew_log);
log_teardown(&the_metrics_log);
}


size_t
spew_get_level(void) {
// Different from DEBUG_spew_get_level in that it acquires a lock and can be used.
size_t level;
pthread_mutex_lock(&the_spew_log.mutex); {
level = the_spew_log.spew_level;
} pthread_mutex_unlock(&the_spew_log.mutex);
return level;
}

///////////////////////////////////////////////////////////////////////////
// DEBUG
//

boolint
DEBUG_shutup(boolint suppress)
{
boolint old;

pthread_mutex_lock(&the_spew_log.mutex); {
old = the_spew_log.suppress_spewage;
the_spew_log.suppress_spewage = suppress;
} pthread_mutex_unlock(&the_spew_log.mutex);

return old;
}

size_t
DEBUG_spew_get_level(void)
{
return the_spew_log.spew_level;
}


#if 0
///////////////////////////////////////////////////////////////////////////
// leak-module link hack
//

/* hack to link the leak checker, so that we can enforce
statically that the leak checker does not call spew() */
extern void (*META_HACK_force_linking_of_leak_module)(void);
void (*META_HACK_force_linking_of_leak_module)(void) =
HACK_force_linking_of_leak_module;
#endif
(12-12/14)