text: #include "log.h"
  #include <backtrace-supported.h>
  #include <backtrace.h>
  #include <ccan/array_size/array_size.h>
  #include <ccan/list/list.h>
  #include <ccan/opt/opt.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/memleak.h>
  #include <common/pseudorand.h>
  #include <common/utils.h>
  #include <errno.h>
  #include <fcntl.h>
  #include <inttypes.h>
  #include <lightningd/jsonrpc.h>
  #include <lightningd/jsonrpc_errors.h>
  #include <lightningd/lightningd.h>
  #include <lightningd/options.h>
  #include <signal.h>
  #include <stdio.h>
  #include <sys/stat.h>
  #include <sys/types.h>
  #include <unistd.h>
  
  /* Once we're up and running, this is set up. */
  struct log *crashlog;
  
  struct log_entry {
  	struct list_node list;
  	struct timeabs time;
  	enum log_level level;
  	unsigned int skipped;
  	const char *prefix;
  	char *log;
  	/* Iff LOG_IO */
  	const u8 *io;
  };
  
  struct log_book {
  	size_t mem_used;
  	size_t max_mem;
  	void (*print)(const char *prefix,
  		      enum log_level level,
  		      bool continued,
  		      const struct timeabs *time,
  		      const char *str, const u8 *io, void *arg);
  	void *print_arg;
  	enum log_level print_level;
  	struct timeabs init_time;
  
  	struct list_head log;
  };
  
  struct log {
  	struct log_book *lr;
  	const char *prefix;
  };
  
  static void log_to_file(const char *prefix,
  			enum log_level level,
  			bool continued,
  			const struct timeabs *time,
  			const char *str,
  			const u8 *io,
  			FILE *logf)
  {
  	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));
  	char iso8601_s[sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ")];
  	snprintf(iso8601_s, sizeof(iso8601_s), iso8601_msec_fmt, (int) time->ts.tv_nsec / 1000000);
  
  	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
  		const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]";
  		char *hex = tal_hex(NULL, io);
  		fprintf(logf, "%s %s%s%s %s\n",
  			iso8601_s, prefix, str, dir, hex);
  		tal_free(hex);
  	} else 	if (!continued) {
  		fprintf(logf, "%s %s %s\n", iso8601_s, prefix, str);
  	} else {
  		fprintf(logf, "%s %s \t%s\n", iso8601_s, prefix, str);
  	}
  	fflush(logf);
  }
  
  static void log_to_stdout(const char *prefix,
  			  enum log_level level,
  			  bool continued,
  			  const struct timeabs *time,
  			  const char *str,
  			  const u8 *io, void *unused UNUSED)
  {
  	log_to_file(prefix, level, continued, time, str, io, stdout);
  }
  
  static size_t mem_used(const struct log_entry *e)
  {
  	return sizeof(*e) + strlen(e->log) + 1 + tal_len(e->io);
  }
  
  static size_t prune_log(struct log_book *log)
  {
  	struct log_entry *i, *next, *tail;
  	size_t skipped = 0, deleted = 0;
  
  	/* Never delete the last one. */
  	tail = list_tail(&log->log, struct log_entry, list);
  
  	list_for_each_safe(&log->log, i, next, list) {
  		/* 50% chance of deleting IO_IN, 25% IO_OUT, 12.5% DEBUG... */
  		if (i == tail || !pseudorand(2 << i->level)) {
  			i->skipped += skipped;
  			skipped = 0;
  			continue;
  		}
  
  		list_del_from(&log->log, &i->list);
  		log->mem_used -= mem_used(i);
  		tal_free(i);
  		skipped++;
  		deleted++;
  	}
  
  	assert(!skipped);
  	return deleted;
  }
  
  struct log_book *new_log_book(size_t max_mem,
  			      enum log_level printlevel)
  {
  	struct log_book *lr = tal_linkable(tal(NULL, struct log_book));
  
  	/* Give a reasonable size for memory limit! */
  	assert(max_mem > sizeof(struct log) * 2);
  	lr->mem_used = 0;
  	lr->max_mem = max_mem;
  	lr->print = log_to_stdout;
  	lr->print_level = printlevel;
  	lr->init_time = time_now();
  	list_head_init(&lr->log);
  
  	return lr;
  }
  
  /* With different entry points */
  struct log *PRINTF_FMT(3,4)
  new_log(const tal_t *ctx, struct log_book *record, const char *fmt, ...)
  {
  	struct log *log = tal(ctx, struct log);
  	va_list ap;
  
  	log->lr = tal_link(log, record);
  	va_start(ap, fmt);
  	/* log->lr owns this, since its entries keep a pointer to it. */
  	/* FIXME: Refcount this! */
  	log->prefix = notleak(tal_vfmt(log->lr, fmt, ap));
  	va_end(ap);
  
  	return log;
  }
  
  struct log_book *get_log_book(const struct log *log)
  {
  	return log->lr;
  }
  
  enum log_level get_log_level(struct log_book *lr)
  {
  	return lr->print_level;
  }
  
  void set_log_level(struct log_book *lr, enum log_level level)
  {
  	lr->print_level = level;
  }
  
  void set_log_prefix(struct log *log, const char *prefix)
  {
  	/* log->lr owns this, since it keeps a pointer to it. */
  	log->prefix = tal_strdup(log->lr, prefix);
  }
  
  void set_log_outfn_(struct log_book *lr,
  		    void (*print)(const char *prefix,
  				  enum log_level level,
  				  bool continued,
  				  const struct timeabs *time,
  				  const char *str, const u8 *io, void *arg),
  		    void *arg)
  {
  	lr->print = print;
  	lr->print_arg = arg;
  }
  
  const char *log_prefix(const struct log *log)
  {
  	return log->prefix;
  }
  
  size_t log_max_mem(const struct log_book *lr)
  {
  	return lr->max_mem;
  }
  
  size_t log_used(const struct log_book *lr)
  {
  	return lr->mem_used;
  }
  
  const struct timeabs *log_init_time(const struct log_book *lr)
  {
  	return &lr->init_time;
  }
  
  static void add_entry(struct log *log, struct log_entry *l)
  {
  	log->lr->mem_used += mem_used(l);
  	list_add_tail(&log->lr->log, &l->list);
  
  	if (log->lr->mem_used > log->lr->max_mem) {
  		size_t old_mem = log->lr->mem_used, deleted;
  		deleted = prune_log(log->lr);
  		log_debug(log, "Log pruned %zu entries (mem %zu -> %zu)",
  			  deleted, old_mem, log->lr->mem_used);
  	}
  }
  
  static struct log_entry *new_log_entry(struct log *log, enum log_level level)
  {
  	struct log_entry *l = tal(log->lr, struct log_entry);
  
  	l->time = time_now();
  	l->level = level;
  	l->skipped = 0;
  	l->prefix = log->prefix;
  	l->io = NULL;
  
  	return l;
  }
  
  static void maybe_print(const struct log *log, const struct log_entry *l,
  			size_t offset)
  {
  	if (l->level >= log->lr->print_level)
  		log->lr->print(log->prefix, l->level, offset != 0,
  			       &l->time, l->log + offset,
  			       l->io, log->lr->print_arg);
  }
  
  void logv(struct log *log, enum log_level level, const char *fmt, va_list ap)
  {
  	int save_errno = errno;
  	struct log_entry *l = new_log_entry(log, level);
  
  	l->log = tal_vfmt(l, fmt, ap);
  
  	size_t log_len = strlen(l->log);
  
  	/* Sanitize any non-printable characters, and replace with '?' */
  	for (size_t i=0; i<log_len; i++)
  		if (l->log[i] < ' ' || l->log[i] >= 0x7f)
  			l->log[i] = '?';
  
  	maybe_print(log, l, 0);
  
  	add_entry(log, l);
  	errno = save_errno;
  }
  
  void log_io(struct log *log, enum log_level dir,
  	    const char *str TAKES,
  	    const void *data TAKES, size_t len)
  {
  	int save_errno = errno;
  	struct log_entry *l = new_log_entry(log, dir);
  
  	assert(dir == LOG_IO_IN || dir == LOG_IO_OUT);
  
  	l->log = tal_strdup(l, str);
  	l->io = tal_dup_arr(l, u8, data, len, 0);
  
  	maybe_print(log, l, 0);
  	add_entry(log, l);
  	errno = save_errno;
  }
  
  void logv_add(struct log *log, const char *fmt, va_list ap)
  {
  	struct log_entry *l = list_tail(&log->lr->log, struct log_entry, list);
  	size_t oldlen = strlen(l->log);
  
  	/* Remove from list, so it doesn't get pruned. */
  	log->lr->mem_used -= mem_used(l);
  	list_del_from(&log->lr->log, &l->list);
  
  	tal_append_vfmt(&l->log, fmt, ap);
  
  	/* Sanitize any non-printable characters, and replace with '?' */
  	for (size_t i=oldlen; i<strlen(l->log); i++)
  		if (l->log[i] < ' ' || l->log[i] >= 0x7f)
  			l->log[i] = '?';
  
  	add_entry(log, l);
  
  	maybe_print(log, l, oldlen);
  }
  
  void log_(struct log *log, enum log_level level, const char *fmt, ...)
  {
  	va_list ap;
  
  	va_start(ap, fmt);
  	logv(log, level, fmt, ap);
  	va_end(ap);
  }
  
  void log_add(struct log *log, const char *fmt, ...)
  {
  	va_list ap;
  
  	va_start(ap, fmt);
  	logv_add(log, fmt, ap);
  	va_end(ap);
  }
  
  void log_each_line_(const struct log_book *lr,
  		    void (*func)(unsigned int skipped,
  				 struct timerel time,
  				 enum log_level level,
  				 const char *prefix,
  				 const char *log,
  				 const u8 *io,
  				 void *arg),
  		    void *arg)
  {
  	const struct log_entry *i;
  
  	list_for_each(&lr->log, i, list) {
  		func(i->skipped, time_between(i->time, lr->init_time),
  		     i->level, i->prefix, i->log, i->io, arg);
  	}
  }
  
  struct log_data {
  	int fd;
  	const char *prefix;
  };
  
  static void log_one_line(unsigned int skipped,
  			 struct timerel diff,
  			 enum log_level level,
  			 const char *prefix,
  			 const char *log,
  			 const u8 *io,
  			 struct log_data *data)
  {
  	char buf[101];
  
  	if (skipped) {
  		sprintf(buf, "%s... %u skipped...", data->prefix, skipped);
  		write_all(data->fd, buf, strlen(buf));
  		data->prefix = "\n";
  	}
  
  	sprintf(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_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, strlen(log));
  	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
  		size_t off, used, len = tal_count(io);
  
  		/* No allocations, may be in signal handler. */
  		for (off = 0; off < len; off += used) {
  			used = len - 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 {
  	const char *name;
  	enum log_level level;
  } log_levels[] = {
  	{ "IO", LOG_IO_OUT },
  	{ "DEBUG", LOG_DBG },
  	{ "INFO", LOG_INFORM },
  	{ "UNUSUAL", LOG_UNUSUAL },
  	{ "BROKEN", LOG_BROKEN }
  };
  
  static char *arg_log_level(const char *arg, struct log *log)
  {
  	size_t i;
  
  	for (i = 0; i < ARRAY_SIZE(log_levels); i++) {
  		if (strcasecmp(arg, log_levels[i].name) == 0) {
  			set_log_level(log->lr, log_levels[i].level);
  			return NULL;
  		}
  	}
  	return tal_fmt(NULL, "unknown log level");
  }
  
  static void show_log_level(char buf[OPT_SHOW_LEN], const struct log *log)
  {
  	size_t i;
  
  	for (i = 0; i < ARRAY_SIZE(log_levels); i++) {
  		if (log->lr->print_level == log_levels[i].level) {
  			strncpy(buf, log_levels[i].name, OPT_SHOW_LEN-1);
  			return;
  		}
  	}
  	abort();
  }
  
  static char *arg_log_prefix(const char *arg, struct log *log)
  {
  	set_log_prefix(log, arg);
  	return NULL;
  }
  
  static void show_log_prefix(char buf[OPT_SHOW_LEN], const struct log *log)
  {
  	strncpy(buf, log->prefix, OPT_SHOW_LEN);
  }
  
  char *arg_log_to_file(const char *arg, struct lightningd *ld)
  {
  	FILE *logf;
  
  	if (ld->logfile) {
  		fclose(ld->log->lr->print_arg);
  		ld->logfile = tal_free(ld->logfile);
  	}
  	ld->logfile = tal_strdup(ld, arg);
  	logf = fopen(arg, "a");
  	if (!logf)
  		return tal_fmt(NULL, "Failed to open: %s", strerror(errno));
  	set_log_outfn(ld->log->lr, log_to_file, logf);
  	return NULL;
  }
  
  void opt_register_logging(struct lightningd *ld)
  {
  	opt_register_arg("--log-level", arg_log_level, show_log_level, ld->log,
  			 "log level (debug, info, unusual, broken)");
  	opt_register_arg("--log-prefix", arg_log_prefix, show_log_prefix,
  			 ld->log,
  			 "log prefix");
  	opt_register_arg("--log-file=<file>", arg_log_to_file, NULL, ld,
  			 "log to file instead of stdout");
  }
  
  void log_backtrace_print(const char *fmt, ...)
  {
  	va_list ap;
  
  	if (!crashlog)
  		return;
  
  	va_start(ap, fmt);
  	logv(crashlog, LOG_BROKEN, fmt, ap);
  	va_end(ap);
  }
  
  static void log_dump_to_file(int fd, const struct log_book *lr)
  {
  	const struct log_entry *i;
  	char buf[100];
  	int len;
  	struct log_data data;
  	time_t start;
  
  	write_all(fd, "Start of new crash log\n",
  		  strlen("Start of new crash log\n"));
  
  	i = list_top(&lr->log, const struct log_entry, list);
  	if (!i) {
  		write_all(fd, "0 bytes:\n\n", strlen("0 bytes:\n\n"));
  		return;
  	}
  
  	start = lr->init_time.ts.tv_sec;
  	len = sprintf(buf, "%zu bytes, %s", lr->mem_used, ctime(&start));
  	write_all(fd, buf, len);
  
  	/* ctime includes \n... WTF? */
  	data.prefix = "";
  	data.fd = fd;
  	log_each_line(lr, log_one_line, &data);
  	write_all(fd, "\n\n", strlen("\n\n"));
  }
  
  /* FIXME: Dump peer logs! */
  void log_backtrace_exit(void)
  {
  	if (!crashlog)
  		return;
  
  	/* If we're not already pointing at a log file, make one */
  	if (crashlog->lr->print == log_to_stdout) {
  		const char *logfile = NULL;
  		int fd;
  
  		/* We expect to be in config dir. */
  		logfile = "crash.log";
  		fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 0600);
  		if (fd < 0) {
  			logfile = "/tmp/lightning-crash.log";
  			fd = open(logfile, O_WRONLY|O_CREAT, 0600);
  		}
  
  		/* Dump entire log. */
  		if (fd >= 0) {
  			log_dump_to_file(fd, crashlog->lr);
  			close(fd);
  			fprintf(stderr, "Log dumped in %s\n", logfile);
  		}
  	}
  }
  
  void fatal(const char *fmt, ...)
  {
  	va_list ap;
  
  	va_start(ap, fmt);
  	vfprintf(stderr, fmt, ap);
  	fprintf(stderr, "\n");
  	va_end(ap);
  
  	if (!crashlog)
  		exit(1);
  
  	va_start(ap, fmt);
  	logv(crashlog, LOG_BROKEN, fmt, ap);
  	va_end(ap);
  	abort();
  }
  
  struct log_info {
  	enum log_level level;
  	struct json_result *response;
  	unsigned int num_skipped;
  };
  
  static void add_skipped(struct log_info *info)
  {
  	if (info->num_skipped) {
  		json_object_start(info->response, NULL);
  		json_add_string(info->response, "type", "SKIPPED");
  		json_add_num(info->response, "num_skipped", info->num_skipped);
  		json_object_end(info->response);
  		info->num_skipped = 0;
  	}
  }
  
  static void json_add_time(struct json_result *result, const char *fieldname,
  			  struct timespec ts)
  {
  	char timebuf[100];
  
  	sprintf(timebuf, "%lu.%09u",
  		(unsigned long)ts.tv_sec,
  		(unsigned)ts.tv_nsec);
  	json_add_string(result, fieldname, timebuf);
  }
  
  static void log_to_json(unsigned int skipped,
  			struct timerel diff,
  			enum log_level level,
  			const char *prefix,
  			const char *log,
  			const u8 *io,
  			struct log_info *info)
  {
  	info->num_skipped += skipped;
  
  	if (level < info->level) {
  		info->num_skipped++;
  		return;
  	}
  
  	add_skipped(info);
  
  	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_IO_IN ? "IO_IN"
  			: level == LOG_IO_OUT ? "IO_OUT"
  			: "UNKNOWN");
  	json_add_time(info->response, "time", diff.ts);
  	json_add_string(info->response, "source", prefix);
  	json_add_string(info->response, "log", log);
  	if (io)
  		json_add_hex(info->response, "data", io, tal_count(io));
  
  	json_object_end(info->response);
  }
  
  void json_add_log(struct json_result *response,
  		  const struct log_book *lr, enum log_level minlevel)
  {
  	struct log_info info;
  
  	info.level = minlevel;
  	info.response = response;
  	info.num_skipped = 0;
  
  	json_array_start(info.response, "log");
  	log_each_line(lr, log_to_json, &info);
  	add_skipped(&info);
  	json_array_end(info.response);
  }
  
  bool json_tok_loglevel(const char *buffer, const jsmntok_t *tok,
  		       enum log_level *level)
  {
  	if (json_tok_streq(buffer, tok, "io"))
  		*level = LOG_IO_OUT;
  	else if (json_tok_streq(buffer, tok, "debug"))
  		*level = LOG_DBG;
  	else if (json_tok_streq(buffer, tok, "info"))
  		*level = LOG_INFORM;
  	else if (json_tok_streq(buffer, tok, "unusual"))
  		*level = LOG_UNUSUAL;
  	else
  		return false;
  	return true;
  }
  
  static void json_getlog(struct command *cmd,
  			const char *buffer, const jsmntok_t *params)
  {
  	struct json_result *response = new_json_result(cmd);
  	enum log_level minlevel;
  	struct log_book *lr = cmd->ld->log_book;
  	jsmntok_t *level;
  
  	if (!json_get_params(cmd, buffer, params, "?level", &level, NULL)) {
  		return;
  	}
  
  	if (!level)
  		minlevel = LOG_INFORM;
  	else if (!json_tok_loglevel(buffer, level, &minlevel)) {
  		command_fail(cmd, JSONRPC2_INVALID_PARAMS, "Invalid level param");
  		return;
  	}
  
  	json_object_start(response, NULL);
  	if (deprecated_apis)
  		json_add_time(response, "creation_time", log_init_time(lr)->ts);
  	json_add_time(response, "created_at", log_init_time(lr)->ts);
  	json_add_num(response, "bytes_used", (unsigned int)log_used(lr));
  	json_add_num(response, "bytes_max", (unsigned int)log_max_mem(lr));
  	json_add_log(response, lr, minlevel);
  	json_object_end(response);
  	command_success(cmd, response);
  }
  
  static const struct json_command getlog_command = {
  	"getlog",
  	json_getlog,
  	"Show logs, with optional log {level} (info|unusual|debug|io)"
  };
  AUTODATA(json_command, &getlog_command);
  