palladum-lightning/lightningd/log.c

#include "config.h"
#include <ccan/cast/cast.h>
#include <ccan/err/err.h>
#include <ccan/io/io.h>
#include <ccan/read_write_all/read_write_all.h>
#include <ccan/str/hex/hex.h>
#include <ccan/tal/link/link.h>
#include <ccan/tal/str/str.h>
#include <common/clock_time.h>
#include <common/configvar.h>
#include <common/json_command.h>
#include <common/memleak.h>
#include <errno.h>
#include <fcntl.h>
#include <lightningd/log.h>
#include <lightningd/notification.h>
#include <stdio.h>

/* What logging level to use if they didn't specify */
#define DEFAULT_LOGLEVEL LOG_INFORM

/* Once we're up and running, this is set up. */
struct logger *crashlog;

/* Reference counted log_prefix.  Log entries keep a pointer, and they
 * can outlast the log entry point which created them. */
struct log_prefix {
	size_t refcnt;
	const char *prefix;
};

struct log_hdr {
	struct timeabs time;
	enum log_level level;
	struct node_id_cache *nc;
	struct log_prefix *prefix;
	size_t msglen, iolen;
	/* Followed by msglen then iolen bytes! */
};

struct print_filter {
	/* In list log_book->print_filters / log_file->print_filters */
	struct list_node list;

	const char *prefix;
	enum log_level level;
};

struct log_file {
	struct list_head print_filters;
	FILE *f;
};

#define RING_BITS 24
struct log_book {
	struct list_head print_filters;

	/* Ring buffer: 16MB should be enough for anyone! */
	char ringbuf[1 << RING_BITS];
	/* These free-run, so use modulus */
	size_t ringbuf_start, ringbuf_end;

	/* Non-null once it's been initialized */
	enum log_level *default_print_level;
	struct timeabs init_time;

	/* Our loggers */
	struct list_head loggers;

	/* Array of log files: one per ld->logfiles[] */
	struct log_file **log_files;
	bool print_timestamps;

	/* Prefix this to every entry as you output */
	const char *prefix;

	/* Although log_book will copy log entries to parent log_book
	 * (the log_book belongs to lightningd), a pointer to lightningd
	 *  is more directly because the notification needs ld->plugins.
	 */
	struct lightningd *ld;
	/* Cache of all node_ids, to avoid multiple copies. */
	struct node_id_map *cache;
};

struct logger {
	/* Inside log_book->loggers. */
	struct list_node list;
	struct log_book *log_book;
	const struct node_id *default_node_id;
	struct log_prefix *prefix;

	/* Print log message at >= this level */
	enum log_level print_level;
	/* For non-trivial setups, we might need to test filters again
	 * when actually producing output. */
	bool need_refiltering;
};

static struct log_prefix *log_prefix_new(const tal_t *ctx,
					 const char *prefix TAKES)
{
	struct log_prefix *lp = tal(ctx, struct log_prefix);
	lp->refcnt = 1;
	lp->prefix = tal_strdup(lp, prefix);
	return lp;
}

static void ringbuf_span(const struct log_book *log,
			 size_t start, size_t len,
			 void **buf1, size_t *buf1len,
			 void **buf2, size_t *buf2len)
{
	size_t size = sizeof(log->ringbuf);
	size_t off  = start % size;
	size_t first = size - off;

	assert(len <= size);

	if (first > len)
		first = len;

	*buf1 = (void *)(log->ringbuf + off);
	*buf1len = first;

	if (first == len) {
		*buf2 = NULL;
		*buf2len = 0;
	} else {
		*buf2 = (void *)log->ringbuf;
		*buf2len = len - first;
	}
}

/* buf1/buf1len & buf2/buf2len -> dest/destlen */
static size_t copy_from(void *dest, size_t destlen,
			const void *buf1, size_t buf1len,
			const void *buf2, size_t buf2len)
{
	assert(destlen == buf1len + buf2len);
	if (buf1len)
		memcpy(dest, buf1, buf1len);
	if (buf2len)
		memcpy((char *)dest + buf1len, buf2, buf2len);
	return destlen;
}

/* dest/destlen -> buf1/buf1len & buf2/buf2len */
static size_t copy_to(void *buf1, size_t buf1len,
		      void *buf2, size_t buf2len,
		      const void *dest, size_t destlen)
{
	assert(destlen == buf1len + buf2len);
	if (buf1len)
		memcpy(buf1, dest, buf1len);
	if (buf2len)
		memcpy(buf2, (char *)dest + buf1len, buf2len);
	return destlen;
}

static size_t ringbuf_used(const struct log_book *log)
{
	return log->ringbuf_end - log->ringbuf_start;
}

static size_t ringbuf_avail(const struct log_book *log)
{
	return sizeof(log->ringbuf) - ringbuf_used(log);
}

static void log_prefix_drop(struct log_prefix *lp)
{
	if (--lp->refcnt == 0)
		tal_free(lp);
}

/* Returns in-place, but copies if it has to.  Updates *off. */
static bool get_log_entry(const tal_t *ctx,
			  const struct log_book *log,
			  struct log_hdr *hdr,
			  const char **msg,
			  const u8 **io,
			  size_t *off)
{
	void *buf1, *buf2;
	size_t buf1len, buf2len;

	if (ringbuf_used(log) < *off + sizeof(*hdr))
		return false;

	ringbuf_span(log, log->ringbuf_start + *off, sizeof(*hdr),
		     &buf1, &buf1len, &buf2, &buf2len);
	*off += copy_from(hdr, sizeof(*hdr), buf1, buf1len, buf2, buf2len);
	ringbuf_span(log, log->ringbuf_start + *off, hdr->msglen,
		     &buf1, &buf1len, &buf2, &buf2len);
	if (buf2len != 0) {
		char *bytes = tal_arr(ctx, char, buf1len + buf2len);
		*off += copy_from(bytes, tal_bytelen(bytes), buf1, buf1len, buf2, buf2len);
		*msg = bytes;
	} else {
		*msg = buf1;
		*off += buf1len;
	}
	ringbuf_span(log, log->ringbuf_start + *off, hdr->iolen,
		     &buf1, &buf1len, &buf2, &buf2len);
	if (buf2len != 0) {
		 u8 *bytes = tal_arr(ctx, u8, buf1len + buf2len);
		 *off += copy_from(bytes, tal_bytelen(bytes), buf1, buf1len, buf2, buf2len);
		 *io = bytes;
	} else {
		if (buf1len == 0)
			*io = NULL;
		else {
			*io = buf1;
			*off += buf1len;
		}
	}
	return true;
}

static struct log_prefix *log_prefix_get(struct log_prefix *lp)
{
	assert(lp->refcnt);
	lp->refcnt++;
	return lp;
}

/* Avoids duplicate node_id entries. */
struct node_id_cache {
	size_t count;
	struct node_id node_id;
};

static const struct node_id *node_cache_id(const struct node_id_cache *nc)
{
	return &nc->node_id;
}

static bool node_id_cache_eq(const struct node_id_cache *nc,
			     const struct node_id *node_id)
{
	return node_id_eq(&nc->node_id, node_id);
}

HTABLE_DEFINE_NODUPS_TYPE(struct node_id_cache,
			  node_cache_id, node_id_hash, node_id_cache_eq,
			  node_id_map);

static void del_front_log(struct log_book *log)
{
	struct log_hdr hdr;
	void *buf1, *buf2;
	size_t buf1len, buf2len;

	ringbuf_span(log, log->ringbuf_start, sizeof(hdr),
		     &buf1, &buf1len, &buf2, &buf2len);
	copy_from(&hdr, sizeof(hdr), buf1, buf1len, buf2, buf2len);
	assert(ringbuf_used(log) >= sizeof(hdr) + hdr.msglen + hdr.iolen);
	log->ringbuf_start += sizeof(hdr) + hdr.msglen + hdr.iolen;

	if (hdr.nc && --hdr.nc->count == 0)
		tal_free(hdr.nc);
	log_prefix_drop(hdr.prefix);
}

/* We truncate genuinely giant messages */
static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg)
{
	const size_t max = sizeof(((struct log_book *)0)->ringbuf) / 64;
	if (hdr->msglen > max) {
		msg = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s",
			      hdr->msglen, (int)max, msg);
		hdr->msglen = strlen(msg);
	}
	if (hdr->iolen > max) {
		msg = tal_fmt(ctx, "[TRUNCATED IO from %zu bytes]: %.*s",
			      hdr->iolen, (int)hdr->msglen, msg);
		hdr->msglen = strlen(msg);
		hdr->iolen = max;
	}
	return cast_const(char *, msg);
}

static void add_entry(struct log_book *log,
		      const struct log_hdr *hdr,
		      const char *msg,
		      const u8 *io)
{
	void *buf1, *buf2;
	size_t buf1len, buf2len;
	size_t needed = sizeof(*hdr) + hdr->msglen + hdr->iolen;
	assert(needed < sizeof(log->ringbuf));

	while (ringbuf_avail(log) < needed)
		del_front_log(log);

	ringbuf_span(log, log->ringbuf_end, sizeof(*hdr), &buf1, &buf1len, &buf2, &buf2len);
	log->ringbuf_end += copy_to(buf1, buf1len, buf2, buf2len, hdr, sizeof(*hdr));
	ringbuf_span(log, log->ringbuf_end, hdr->msglen, &buf1, &buf1len, &buf2, &buf2len);
	log->ringbuf_end += copy_to(buf1, buf1len, buf2, buf2len, msg, hdr->msglen);
	ringbuf_span(log, log->ringbuf_end, hdr->iolen, &buf1, &buf1len, &buf2, &buf2len);
	log->ringbuf_end += copy_to(buf1, buf1len, buf2, buf2len, io, hdr->iolen);
}

static const char *level_prefix(enum log_level level)
{
	switch (level) {
	case LOG_IO_OUT:
	case LOG_IO_IN:
		return "IO     ";
	case LOG_TRACE:
		return "TRACE  ";
	case LOG_DBG:
		return "DEBUG  ";
	case LOG_INFORM:
		return "INFO   ";
	case LOG_UNUSUAL:
		return "UNUSUAL";
	case LOG_BROKEN:
		return "**BROKEN**";
	}
	abort();
}

/* What do these filters say about level to log this entry at? */
static bool filter_level(const struct list_head *print_filters,
			 const char *prefix,
			 const char *node_id_str,
			 enum log_level *level)
{
	struct print_filter *i;

	list_for_each(print_filters, i, list) {
		if (strstr(prefix, i->prefix) || strstr(node_id_str, i->prefix)) {
			*level = i->level;
			return true;
		}
	}
	return false;
}

/* What's the lowest filtering which could possibly apply? */
static void lowest_filter(const struct list_head *print_filters,
			  const char *prefix,
			  const struct node_id *node_id,
			  enum log_level *level)
{
	struct print_filter *i;
	const char *node_id_str;

	if (node_id)
		node_id_str = fmt_node_id(tmpctx, node_id);
	else
		node_id_str = NULL;

	list_for_each(print_filters, i, list) {
		bool match;

		if (strstr(prefix, i->prefix))
			match = true;
		else if (node_id_str) {
			match = (strstr(node_id_str, i->prefix) != NULL);
		} else {
			/* Could this possibly match a node_id? */
			match = strstarts(i->prefix, "02") || strstarts(i->prefix, "03");
		}

		if (match && i->level < *level) {
			*level = i->level;
		}
	}
}

static void log_to_files(const char *log_prefix,
			 const char *entry_prefix,
			 enum log_level level,
			 /* The node_id to log under. */
			 const struct node_id *node_id,
			 /* Filters to apply, if non-NULL */
			 const struct list_head *print_filters,
			 const struct timeabs *time,
			 const char *str, size_t str_len,
			 const u8 *io, size_t io_len,
			 bool print_timestamps,
			 const enum log_level *default_print_level,
			 struct log_file **log_files)
{
	char tstamp[sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ ")];
	char *entry, nodestr[hex_str_size(PUBKEY_CMPR_LEN)];
	char buf[sizeof("%s%s%s %s-%s: %s\n")
		 + strlen(log_prefix)
		 + sizeof(tstamp)
		 + strlen(level_prefix(level))
		 + sizeof(nodestr)
		 + strlen(entry_prefix)
		 + str_len];
	bool filtered;

	if (print_timestamps) {
		char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ ")];
		strftime(iso8601_msec_fmt, sizeof(iso8601_msec_fmt), "%FT%T.%%03dZ ", gmtime(&time->ts.tv_sec));
		snprintf(tstamp, sizeof(tstamp), iso8601_msec_fmt, (int) time->ts.tv_nsec / 1000000);
	} else
		tstamp[0] = '\0';

	if (node_id)
		hex_encode(node_id->k, sizeof(node_id->k),
			   nodestr, sizeof(nodestr));
	else
		nodestr[0] = '\0';
	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
		const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]";
		char *hex = tal_hexstr(NULL, io, io_len);
		if (!node_id)
			entry = tal_fmt(tmpctx, "%s%s%s: %.*s%s %s\n",
					log_prefix, tstamp, entry_prefix, (int)str_len, str, dir, hex);
		else
			entry = tal_fmt(tmpctx, "%s%s%s-%s: %.*s%s %s\n",
					log_prefix, tstamp,
					nodestr,
					entry_prefix, (int)str_len, str, dir, hex);
		tal_free(hex);
	} else {
		size_t len;
		entry = buf;
		if (!node_id)
			len = snprintf(buf, sizeof(buf),
				       "%s%s%s %s: %.*s\n",
				       log_prefix, tstamp, level_prefix(level), entry_prefix, (int)str_len, str);
		else
			len = snprintf(buf, sizeof(buf), "%s%s%s %s-%s: %.*s\n",
				       log_prefix, tstamp, level_prefix(level),
				       nodestr,
				       entry_prefix, (int)str_len, str);
		assert(len < sizeof(buf));
	}

	/* In complex configurations, we tell loggers to overshare: then we
	 * need to filter here to see if we really want it. */
	filtered = false;
	if (print_filters) {
		enum log_level filter;
		if (filter_level(print_filters,
				 entry_prefix, nodestr, &filter)) {
			if (level < filter)
				return;
			/* Even if they specify a default filter level of 'INFO', this overrides */
			filtered = true;
		}
	}

	/* Default if nothing set is stdout */
	if (!log_files) {
		fwrite(entry, strlen(entry), 1, stdout);
		fflush(stdout);
	}

	/* We may have to apply per-file filters. */
	for (size_t i = 0; i < tal_count(log_files); i++) {
		enum log_level filter;
		if (!filter_level(&log_files[i]->print_filters,
				  entry_prefix, nodestr, &filter)) {
			/* If we haven't set default yet, only log UNUSUAL */
			if (!default_print_level)
				filter = LOG_UNUSUAL;
			else {
				/* If we've filtered it already, it passes */
				if (filtered)
					filter = level;
				else
					filter = *default_print_level;
			}
		}
		if (level < filter)
			continue;
		fwrite(entry, strlen(entry), 1, log_files[i]->f);
		fflush(log_files[i]->f);
	}
}

static void destroy_log_book(struct log_book *log)
{
	while (ringbuf_used(log) > 0)
		del_front_log(log);
}

struct log_book *new_log_book(struct lightningd *ld)
{
	struct log_book *log_book = tal_linkable(tal(NULL, struct log_book));

	log_book->ringbuf_start = log_book->ringbuf_end = 0;
	log_book->log_files = NULL;
	log_book->default_print_level = NULL;
	/* We have to allocate this, since we tal_free it on resetting */
	log_book->prefix = tal_strdup(log_book, "");
	list_head_init(&log_book->print_filters);
	list_head_init(&log_book->loggers);
	log_book->init_time = clock_time();
	log_book->ld = ld;
	log_book->cache = tal(log_book, struct node_id_map);
	node_id_map_init(log_book->cache);
	log_book->print_timestamps = true;
	tal_add_destructor(log_book, destroy_log_book);

	return log_book;
}

/* What's the minimum level to print this prefix and node_id for this
 * log book?  Saves us marshalling long print lines in most cases. */
static enum log_level print_level(struct log_book *log_book,
				  const struct log_prefix *lp,
				  const struct node_id *node_id,
				  bool *need_refiltering)
{
	enum log_level level = *log_book->default_print_level;
	bool have_filters = false;

	lowest_filter(&log_book->print_filters, lp->prefix, node_id, &level);
	if (!list_empty(&log_book->print_filters))
		have_filters = true;

	/* We need to look into per-file filters as well: might give a
	 * lower filter! */
	for (size_t i = 0; i < tal_count(log_book->log_files); i++) {
		lowest_filter(&log_book->log_files[i]->print_filters,
			      lp->prefix, node_id, &level);
		if (!list_empty(&log_book->log_files[i]->print_filters))
			have_filters = true;
	}

	/* Almost any complex array of filters can mean we want to re-check
	 * when logging. */
	if (need_refiltering)
		*need_refiltering = have_filters;

	return level;
}

static void destroy_logger(struct logger *log)
{
	list_del_from(&log->log_book->loggers, &log->list);
}

/* With different entry points */
struct logger *
new_logger(const tal_t *ctx, struct log_book *log_book,
	   const struct node_id *default_node_id,
	   const char *fmt, ...)
{
	struct logger *log = tal(ctx, struct logger);
	va_list ap;

	log->log_book = tal_link(log, log_book);
	va_start(ap, fmt);
	/* Owned by the log book itself, since it can be referenced
	 * by log entries, too */
	log->prefix = log_prefix_new(log->log_book, take(tal_vfmt(NULL, fmt, ap)));
	va_end(ap);
	log->default_node_id = tal_dup_or_null(log, struct node_id,
					       default_node_id);

	/* Still initializing?  Print UNUSUAL / BROKEN messages only  */
	if (!log->log_book->default_print_level) {
		log->print_level = LOG_UNUSUAL;
		log->need_refiltering = false;
	} else {
		log->print_level = print_level(log->log_book,
					       log->prefix,
					       default_node_id,
					       &log->need_refiltering);
	}
	list_add(&log->log_book->loggers, &log->list);
	tal_add_destructor(log, destroy_logger);
	return log;
}

const char *log_prefix(const struct logger *log)
{
	return log->prefix->prefix;
}

bool log_has_io_logging(const struct logger *log)
{
	return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_TRACE;
}

bool log_has_trace_logging(const struct logger *log)
{
	return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_DBG;
}

static void destroy_node_id_cache(struct node_id_cache *nc, struct log_book *log_book)
{
	node_id_map_del(log_book->cache, nc);
}

static void maybe_print(struct logger *log,
			const struct log_hdr *l,
			const char *logmsg,
			const u8 *iomsg)
{
	if (l->level >= log->print_level)
		log_to_files(log->log_book->prefix, log->prefix->prefix, l->level,
			     l->nc ? &l->nc->node_id : NULL,
			     log->need_refiltering ? &log->log_book->print_filters : NULL,
			     &l->time, logmsg, strlen(logmsg),
			     iomsg, l->iolen,
			     log->log_book->print_timestamps,
			     log->log_book->default_print_level,
			     log->log_book->log_files);
}

static void maybe_notify_log(struct logger *log,
			     const struct log_hdr *l,
			     const char *logmsg)
{
	if (l->level >= log->print_level)
		notify_log(log->log_book->ld,
			   l->level,
			   l->time,
			   l->prefix->prefix,
			   logmsg);
}

static void init_log_hdr(const struct logger *log,
			 struct log_hdr *l,
			 enum log_level level,
			 const struct node_id *node_id,
			 size_t msglen, size_t iolen)
{
	l->time = clock_time();
	l->level = level;
	l->prefix = log_prefix_get(log->prefix);
	l->msglen = msglen;
	l->iolen = iolen;
	if (!node_id)
		node_id = log->default_node_id;
	if (node_id) {
		l->nc = node_id_map_get(log->log_book->cache, node_id);
		if (!l->nc) {
			l->nc = tal(log->log_book->cache, struct node_id_cache);
			l->nc->count = 0;
			l->nc->node_id = *node_id;
			node_id_map_add(log->log_book->cache, l->nc);
			tal_add_destructor2(l->nc, destroy_node_id_cache,
					    log->log_book);
		}
		l->nc->count++;
	} else
		l->nc = NULL;
}

void logv(struct logger *log, enum log_level level,
	  const struct node_id *node_id,
	  bool call_notifier,
	  const char *fmt, va_list ap)
{
	int save_errno = errno;
	struct log_hdr l;
	size_t log_len;
	char *logmsg;

	/* This is WARN_UNUSED_RESULT, because everyone should somehow deal
	 * with OOM, even though nobody does. */
	if (vasprintf(&logmsg, fmt, ap) == -1)
		abort();

	log_len = strlen(logmsg);

	/* Sanitize any non-printable characters, and replace with '?' */
	for (size_t i=0; i<log_len; i++)
		if (logmsg[i] < ' ' || logmsg[i] >= 0x7f)
			logmsg[i] = '?';

	init_log_hdr(log, &l, level, node_id, log_len, 0);
	maybe_print(log, &l, logmsg, NULL);
	maybe_notify_log(log, &l, logmsg);

	logmsg = cap_header(tmpctx, &l, logmsg);
	add_entry(log->log_book, &l, logmsg, NULL);

	if (call_notifier)
		notify_warning(log->log_book->ld,
			       l.level,
			       l.time,
			       l.prefix->prefix,
			       logmsg);
	free(logmsg);

	errno = save_errno;
}

void log_io(struct logger *log, enum log_level dir,
	    const struct node_id *node_id,
	    const char *str TAKES,
	    const void *data TAKES, size_t len)
{
	int save_errno = errno;
	struct log_hdr l;

	assert(dir == LOG_IO_IN || dir == LOG_IO_OUT);

	init_log_hdr(log, &l, dir, node_id, strlen(str), len);

	if (l.level >= log->print_level)
		log_to_files(log->log_book->prefix, log->prefix->prefix, l.level,
			     l.nc ? &l.nc->node_id : NULL,
			     log->need_refiltering ? &log->log_book->print_filters : NULL,
			     &l.time, str, strlen(str),
			     data, len,
			     log->log_book->print_timestamps,
			     log->log_book->default_print_level,
			     log->log_book->log_files);

	str = cap_header(tmpctx, &l, str);
	add_entry(log->log_book, &l, str, data);
	errno = save_errno;
}

void log_(struct logger *log, enum log_level level,
	  const struct node_id *node_id,
	  bool call_notifier,
	  const char *fmt, ...)
{
	va_list ap;

	va_start(ap, fmt);
	logv(log, level, node_id, call_notifier, fmt, ap);
	va_end(ap);
}

#define log_each_line(log_book, func, arg)					\
	log_each_line_((log_book),					\
		       typesafe_cb_preargs(void, void *, (func), (arg),	\
					   struct timerel,		\
					   enum log_level,		\
					   const struct node_id *,	\
					   const char *,		\
					   const char *, size_t,	\
					   const u8 *, size_t), (arg))

static void log_each_line_(const struct log_book *log_book,
			   void (*func)(struct timerel time,
					enum log_level level,
					const struct node_id *node_id,
					const char *prefix,
					const char *log,
					size_t loglen,
					const u8 *io,
					size_t iolen,
					void *arg),
			   void *arg)
{
	size_t off = 0;
	const char *msg;
	const u8 *io;
	struct log_hdr l;

	while (get_log_entry(tmpctx, log_book, &l, &msg, &io, &off)) {
		func(time_between(l.time, log_book->init_time),
		     l.level, l.nc ? &l.nc->node_id : NULL,
		     l.prefix->prefix, msg, l.msglen, io, l.iolen, arg);
	}
}

struct log_data {
	int fd;
	const char *prefix;
};

static void log_one_line(struct timerel diff,
			 enum log_level level,
			 const struct node_id *node_id,
			 const char *prefix,
			 const char *log,
			 size_t loglen,
			 const u8 *io,
			 size_t iolen,
			 struct log_data *data)
{
	char buf[101];

	snprintf(buf, sizeof(buf), "%s+%lu.%09u %s%s: ",
		data->prefix,
		(unsigned long)diff.ts.tv_sec,
		(unsigned)diff.ts.tv_nsec,
		prefix,
		level == LOG_IO_IN ? "IO_IN"
		: level == LOG_IO_OUT ? "IO_OUT"
		: level == LOG_TRACE ? "TRACE"
		: level == LOG_DBG ? "DEBUG"
		: level == LOG_INFORM ? "INFO"
		: level == LOG_UNUSUAL ? "UNUSUAL"
		: level == LOG_BROKEN ? "BROKEN"
		: "**INVALID**");

	write_all(data->fd, buf, strlen(buf));
	write_all(data->fd, log, loglen);
	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
		size_t off, used;

		/* No allocations, may be in signal handler. */
		for (off = 0; off < iolen; off += used) {
			used = iolen - off;
			if (hex_str_size(used) > sizeof(buf))
				used = hex_data_size(sizeof(buf));
			hex_encode(io + off, used, buf, hex_str_size(used));
			write_all(data->fd, buf, strlen(buf));
		}
	}

	data->prefix = "\n";
}

static struct log_file *find_log_file(struct log_book *log_book,
				      const char *fname)
{
	assert(tal_count(log_book->log_files)
	       == tal_count(log_book->ld->logfiles));
	for (size_t i = 0; i < tal_count(log_book->log_files); i++) {
		if (streq(log_book->ld->logfiles[i], fname))
			return log_book->log_files[i];
	}
	return NULL;
}

char *opt_log_level(const char *arg, struct log_book *log_book)
{
	enum log_level level;
	int len;

	len = strcspn(arg, ":");
	if (!log_level_parse(arg, len, &level))
		return tal_fmt(tmpctx, "unknown log level %.*s", len, arg);

	if (arg[len]) {
		struct print_filter *f = tal(log_book, struct print_filter);
		f->prefix = arg + len + 1;
		f->level = level;

		/* :<filename> */
		len = strcspn(f->prefix, ":");
		if (f->prefix[len]) {
			struct log_file *lf;
			lf = find_log_file(log_book, f->prefix + len + 1);
			if (!lf)
				return tal_fmt(tmpctx,
					       "unknown log file %s",
					       f->prefix + len + 1);
			f->prefix = tal_strndup(f, f->prefix, len);
			list_add_tail(&lf->print_filters, &f->list);
		} else {
			list_add_tail(&log_book->print_filters, &f->list);
		}
	} else {
		tal_free(log_book->default_print_level);
		log_book->default_print_level = tal(log_book, enum log_level);
		*log_book->default_print_level = level;
	}
	return NULL;
}

void json_add_opt_log_levels(struct json_stream *response, struct log_book *log_book)
{
	struct print_filter *i;

	list_for_each(&log_book->print_filters, i, list) {
		json_add_str_fmt(response, "log-level", "%s:%s",
				 log_level_name(i->level), i->prefix);
	}
}

static bool show_log_level(char *buf, size_t len, const struct log_book *log_book)
{
	enum log_level l;

	if (log_book->default_print_level)
		l = *log_book->default_print_level;
	else
		l = DEFAULT_LOGLEVEL;
	strncpy(buf, log_level_name(l), len);
	return true;
}

static char *arg_log_prefix(const char *arg, struct log_book *log_book)
{
	tal_free(log_book->prefix);
	log_book->prefix = tal_strdup(log_book, arg);
	return NULL;
}

static bool show_log_prefix(char *buf, size_t len, const struct log_book *log_book)
{
	strncpy(buf, log_book->prefix, len);
	/* Default is empty, so don't print that! */
	return !streq(log_book->prefix, "");
}

static int signalfds[2];

static void handle_sighup(int sig)
{
	/* Writes a single 0x00 byte to the signalfds pipe. This may fail if
	 * we're hammered with SIGHUP.  We don't care. */
	if (write(signalfds[1], "", 1))
		;
}

/* Mutual recursion */
static struct io_plan *setup_read(struct io_conn *conn, struct lightningd *ld);

static struct io_plan *rotate_log(struct io_conn *conn, struct lightningd *ld)
{
	log_info(ld->log, "Ending log due to SIGHUP");
	for (size_t i = 0; i < tal_count(ld->log->log_book->log_files); i++) {
		if (streq(ld->logfiles[i], "-"))
			continue;
		fclose(ld->log->log_book->log_files[i]->f);
		ld->log->log_book->log_files[i]->f = fopen(ld->logfiles[i], "a");
		if (!ld->log->log_book->log_files[i]->f)
			err(1, "failed to reopen log file %s", ld->logfiles[i]);
	}

	log_info(ld->log, "Started log due to SIGHUP");
	return setup_read(conn, ld);
}

static struct io_plan *setup_read(struct io_conn *conn, struct lightningd *ld)
{
	/* We read and discard. */
	static char discard;
	return io_read(conn, &discard, 1, rotate_log, ld);
}

static void setup_log_rotation(struct lightningd *ld)
{
	struct sigaction act;
	if (pipe(signalfds) != 0)
		errx(1, "Pipe for signalfds");

	notleak(io_new_conn(ld, signalfds[0], setup_read, ld));

	io_fd_block(signalfds[1], false);
	memset(&act, 0, sizeof(act));
	act.sa_handler = handle_sighup;
	/* We do not need any particular flags; the sigaction
	 * default behavior (EINTR any system calls, pass only
	 * the signo to the handler, retain the same signal
	 * handler throughout) is fine with us.
	 */
	act.sa_flags = 0;
	/* Block all signals while handling SIGHUP.
	 * Without this, e.g. an inopportune SIGCHLD while we
	 * are doing a `write` to the SIGHUP signal pipe could
	 * prevent us from sending the byte and performing the
	 * log rotation in the main loop.
	 *
	 * The SIGHUP handler does very little anyway, and
	 * the blocked signals will get delivered soon after
	 * the SIGHUP handler returns.
	 */
	sigfillset(&act.sa_mask);

	if (sigaction(SIGHUP, &act, NULL) != 0)
		err(1, "Setting up SIGHUP handler");
}

char *arg_log_to_file(const char *arg, struct lightningd *ld)
{
	int size;
	struct log_file *logf;

	if (!ld->logfiles) {
		setup_log_rotation(ld);
		ld->logfiles = tal_arr(ld, const char *, 0);
		ld->log_book->log_files = tal_arr(ld->log_book, struct log_file *, 0);
	}

	logf = tal(ld->log_book->log_files, struct log_file);
	list_head_init(&logf->print_filters);
	if (streq(arg, "-"))
		logf->f = stdout;
	else {
		logf->f = fopen(arg, "a");
		if (!logf->f)
			return tal_fmt(tmpctx, "Failed to open: %s", strerror(errno));
	}

	tal_arr_expand(&ld->logfiles, tal_strdup(ld->logfiles, arg));
	tal_arr_expand(&ld->log_book->log_files, logf);

	/* For convenience make a block of empty lines just like Bitcoin Core */
	size = ftell(logf->f);
	if (size > 0)
		fprintf(logf->f, "\n\n\n\n");

	log_debug(ld->log, "Opened log file %s", arg);
	return NULL;
}

void opt_register_logging(struct lightningd *ld)
{
	opt_register_early_arg("--log-level",
			       opt_log_level, show_log_level, ld->log_book,
			       "log level (io, debug, info, unusual, broken) [:prefix]");
	clnopt_witharg("--log-timestamps", OPT_EARLY|OPT_SHOWBOOL,
		       opt_set_bool_arg, opt_show_bool,
		       &ld->log_book->print_timestamps,
		       "prefix log messages with timestamp");
	clnopt_witharg("--log-prefix", OPT_EARLY|OPT_KEEP_WHITESPACE,
		       arg_log_prefix, show_log_prefix, ld->log_book, "log prefix");
	clnopt_witharg("--log-file=<file>",
		       OPT_EARLY|OPT_MULTI,
		       arg_log_to_file, NULL, ld,
		       "Also log to file (- for stdout)");
}

void logging_options_parsed(struct log_book *log_book)
{
	struct logger *log;
	size_t off;
	const char *msg;
	const u8 *io;
	struct log_hdr l;

	/* If they didn't set an explicit level, set to info */
	if (!log_book->default_print_level) {
		log_book->default_print_level = tal(log_book, enum log_level);
		*log_book->default_print_level = DEFAULT_LOGLEVEL;
	}

	/* Set print_levels for each log, depending on filters. */
	list_for_each(&log_book->loggers, log, list) {
		log->print_level = print_level(log_book,
					       log->prefix,
					       log->default_node_id,
					       &log->need_refiltering);
	}

	/* Catch up, since before we were only printing BROKEN msgs */
	off = 0;
	while (get_log_entry(tmpctx, log_book, &l, &msg, &io, &off)) {
		if (l.level >= print_level(log_book, l.prefix, l.nc ? &l.nc->node_id : NULL, NULL))
			log_to_files(log_book->prefix, l.prefix->prefix, l.level,
				     l.nc ? &l.nc->node_id : NULL,
				     &log_book->print_filters,
				     &l.time, msg, l.msglen,
				     io, l.iolen,
				     log_book->print_timestamps,
				     log_book->default_print_level,
				     log_book->log_files);
	}
}

void log_backtrace_print(const char *fmt, ...)
{
	va_list ap;

	if (!crashlog)
		return;

	va_start(ap, fmt);
	logv(crashlog, LOG_BROKEN, NULL, false, fmt, ap);
	va_end(ap);
}

static void log_dump_to_file(int fd, const struct log_book *log_book)
{
	char buf[100];
	int len;
	struct log_data data;
	time_t start;

	start = log_book->init_time.ts.tv_sec;
	len = snprintf(buf, sizeof(buf), "%zu bytes, %s", ringbuf_used(log_book), ctime(&start));
	write_all(fd, buf, len);

	/* ctime includes \n... WTF? */
	data.prefix = "";
	data.fd = fd;
	log_each_line(log_book, log_one_line, &data);
	write_all(fd, "\n\n", strlen("\n\n"));
}

void log_backtrace_exit(void)
{
	int fd;
	char timebuf[sizeof("YYYYmmddHHMMSS")];
	char logfile[sizeof("/tmp/lightning-crash.log.") + sizeof(timebuf)];
	struct timeabs time = clock_time();

	strftime(timebuf, sizeof(timebuf), "%Y%m%d%H%M%S", gmtime(&time.ts.tv_sec));

	if (!crashlog)
		return;

	/* We expect to be in config dir. */
	snprintf(logfile, sizeof(logfile), "crash.log.%s", timebuf);

	fd = open(logfile, O_WRONLY|O_CREAT|O_TRUNC, 0600);
	if (fd < 0) {
		snprintf(logfile, sizeof(logfile),
			 "/tmp/lightning-crash.log.%s", timebuf);
		fd = open(logfile, O_WRONLY|O_CREAT|O_TRUNC, 0600);
	}

	/* Dump entire log. */
	if (fd >= 0) {
		log_dump_to_file(fd, crashlog->log_book);
		close(fd);
		fprintf(stderr, "Log dumped in %s\n", logfile);
	}
}

void fatal_vfmt(const char *fmt, va_list ap)
{
	va_list ap2;

	/* You are not allowed to re-use va_lists, so make a copy. */
	va_copy(ap2, ap);
	vfprintf(stderr, fmt, ap);
	fprintf(stderr, "\n");

	if (!crashlog)
		exit(1);

	logv(crashlog, LOG_BROKEN, NULL, true, fmt, ap2);
	abort();
	/* va_copy() must be matched with va_end(), even if unreachable. */
	va_end(ap2);
}

void fatal(const char *fmt, ...)
{
	va_list ap;

	va_start(ap, fmt);
	fatal_vfmt(fmt, ap);
	va_end(ap);
}

struct log_info {
	enum log_level level;
	struct json_stream *response;
	/* If non-null, only show messages about this peer */
	const struct node_id *node_id;
};

static void log_to_json(struct timerel diff,
			enum log_level level,
			const struct node_id *node_id,
			const char *prefix,
			const char *log,
			size_t loglen,
			const u8 *io,
			size_t iolen,
			struct log_info *info)
{
	if (info->node_id) {
		if (!node_id || !node_id_eq(node_id, info->node_id))
			return;
	}

	if (level < info->level) {
		return;
	}

	json_object_start(info->response, NULL);
	json_add_string(info->response, "type",
			level == LOG_BROKEN ? "BROKEN"
			: level == LOG_UNUSUAL ? "UNUSUAL"
			: level == LOG_INFORM ? "INFO"
			: level == LOG_DBG ? "DEBUG"
			: level == LOG_TRACE ? "TRACE"
			: level == LOG_IO_IN ? "IO_IN"
			: level == LOG_IO_OUT ? "IO_OUT"
			: "UNKNOWN");
	json_add_timestr(info->response, "time", diff.ts);
	if (node_id)
		json_add_node_id(info->response, "node_id", node_id);
	json_add_string(info->response, "source", prefix);
	json_add_stringn(info->response, "log", log, loglen);
	if (io)
		json_add_hex(info->response, "data", io, iolen);

	json_object_end(info->response);
}

void json_add_log(struct json_stream *response,
		  const struct log_book *log_book,
		  const struct node_id *node_id,
		  enum log_level minlevel)
{
	struct log_info info;

	info.level = minlevel;
	info.response = response;
	info.node_id = node_id;

	json_array_start(info.response, "log");
	log_each_line(log_book, log_to_json, &info);
	json_array_end(info.response);
}

struct command_result *param_loglevel(struct command *cmd,
				      const char *name,
				      const char *buffer,
				      const jsmntok_t *tok,
				      enum log_level **level)
{
	*level = tal(cmd, enum log_level);
	if (log_level_parse(buffer + tok->start, tok->end - tok->start, *level))
		return NULL;

	return command_fail_badparam(cmd, name, buffer, tok,
				     "should be 'io', 'debug', 'info', or "
				     "'unusual'");
}

static struct command_result *json_getlog(struct command *cmd,
					  const char *buffer,
					  const jsmntok_t *obj UNNEEDED,
					  const jsmntok_t * params)
{
	struct json_stream *response;
	enum log_level *minlevel;
	struct log_book *log_book = cmd->ld->log_book;

	if (!param(cmd, buffer, params,
		   p_opt_def("level", param_loglevel, &minlevel, LOG_INFORM),
		   NULL))
		return command_param_failed();

	response = json_stream_success(cmd);
	/* Suppress logging for this stream, to not bloat io logs */
	json_stream_log_suppress_for_cmd(response, cmd);
	json_add_timestr(response, "created_at", log_book->init_time.ts);
	json_add_num(response, "bytes_used", (unsigned int)ringbuf_used(log_book));
	json_add_num(response, "bytes_max", sizeof(log_book->ringbuf));
	json_add_log(response, log_book, NULL, *minlevel);
	return command_success(cmd, response);
}

static const struct json_command getlog_command = {
	"getlog",
	json_getlog,
};
AUTODATA(json_command, &getlog_command);