#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