Support log rotation, don't append crash.log files but use per-peer.

CHANGELOG.md

@@ -19,6 +19,7 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 - Config: `--conf` option to set config file.
 - JSON API: Added description to invoices and payments (#1740).
 - pylightning: RpcError now has `method` and `payload` fields.
+- Sending lightningd a SIGHUP will make it reopen its `log-file`, if any.
 
 ### Changed
 
@@ -38,6 +39,7 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
   their capacity or their `htlc_minimum_msat` parameter (#1777)
 - We now try to connect to all known addresses for a peer, not just
   the one given or the first one announced.
+- Crash logs are now placed one-per file like `crash.log.20180822233752`
 
 ### Deprecated
 

doc/lightningd-config.5

@@ -156,7 +156,7 @@ Prefix for log lines: this can be customized if you want to merge logs with mult
 .PP
 \fBlog\-file\fR=\fIPATH\fR
 .RS 4
-Log to this file instead of stdout\&.
+Log to this file instead of stdout\&. Sending lightningd(1) SIGHUP will cause it to reopen this file (useful for log rotation)\&.
 .RE
 .PP
 \fBrpc\-file\fR=\fIPATH\fR

doc/lightningd-config.5.txt

@@ -109,7 +109,8 @@ Lightning daemon options:
     multiple daemons.
 
 *log-file*='PATH'::
-    Log to this file instead of stdout.
+    Log to this file instead of stdout.  Sending lightningd(1) SIGHUP will cause
+    it to reopen this file (useful for log rotation).
 
 *rpc-file*='PATH'::
     Set JSON-RPC socket (or /dev/tty), such as for lightning-cli(1).

lightningd/log.c

@@ -2,6 +2,8 @@
 #include <backtrace-supported.h>
 #include <backtrace.h>
 #include <ccan/array_size/array_size.h>
+#include <ccan/err/err.h>
+#include <ccan/io/io.h>
 #include <ccan/list/list.h>
 #include <ccan/opt/opt.h>
 #include <ccan/read_write_all/read_write_all.h>
@@ -444,14 +446,69 @@ static void show_log_prefix(char buf[OPT_SHOW_LEN], const struct log *log)
 	strncpy(buf, log->prefix, OPT_SHOW_LEN);
 }
 
+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)
+{
+	FILE *logf;
+
+	log_info(ld->log, "Ending log due to SIGHUP");
+	fclose(ld->log->lr->print_arg);
+
+	logf = fopen(ld->logfile, "a");
+	if (!logf)
+		err(1, "failed to reopen log file %s", ld->logfile);
+	set_log_outfn(ld->log->lr, log_to_file, logf);
+
+	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;
+	act.sa_flags = SA_RESETHAND;
+
+	if (sigaction(SIGHUP, &act, NULL) != 0)
+		err(1, "Setting up SIGHUP handler");
+}
+
 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);
-	}
+	} else
+		setup_log_rotation(ld);
+
 	ld->logfile = tal_strdup(ld, arg);
 	logf = fopen(arg, "a");
 	if (!logf)
@@ -491,9 +548,6 @@ static void log_dump_to_file(int fd, const struct log_book *lr)
 	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"));
@@ -514,28 +568,31 @@ static void log_dump_to_file(int fd, const struct log_book *lr)
 /* FIXME: Dump peer logs! */
 void log_backtrace_exit(void)
 {
+	int fd;
+	char timebuf[sizeof("YYYYmmddHHMMSS")];
+	char logfile[sizeof("/tmp/lightning-crash.log.") + sizeof(timebuf)];
+	struct timeabs time = time_now();
+
+	strftime(timebuf, sizeof(timebuf), "%Y%m%d%H%M%S", gmtime(&time.ts.tv_sec));
+
 	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);
-		}
+	/* We expect to be in config dir. */
+	snprintf(logfile, sizeof(logfile), "crash.log.%s", timebuf);
 
-		/* Dump entire log. */
-		if (fd >= 0) {
-			log_dump_to_file(fd, crashlog->lr);
-			close(fd);
-			fprintf(stderr, "Log dumped in %s\n", logfile);
-		}
+	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->lr);
+		close(fd);
+		fprintf(stderr, "Log dumped in %s\n", logfile);
 	}
 }
 

tests/test_misc.py

@@ -2,12 +2,13 @@
 from fixtures import *  # noqa: F401,F403
 from flaky import flaky
 from lightning import RpcError
-from utils import DEVELOPER, sync_blockheight, only_one, wait_for
+from utils import DEVELOPER, VALGRIND, sync_blockheight, only_one, wait_for, TailableProc
 from ephemeral_port_reserve import reserve
 
 import json
 import os
 import pytest
+import shutil
 import signal
 import socket
 import subprocess
@@ -846,3 +847,39 @@ def test_ipv4_and_ipv6(node_factory):
         assert bind[0]['type'] == 'ipv4'
         assert bind[0]['address'] == '0.0.0.0'
         assert int(bind[0]['port']) == port
+
+
+def test_logging(node_factory):
+    # Since we redirect, node.start() will fail: do manually.
+    l1 = node_factory.get_node(options={'log-file': 'logfile'}, may_fail=True, start=False)
+    logpath = os.path.join(l1.daemon.lightning_dir, 'logfile')
+    logpath_moved = os.path.join(l1.daemon.lightning_dir, 'logfile_moved')
+
+    TailableProc.start(l1.daemon)
+    wait_for(lambda: os.path.exists(logpath))
+
+    shutil.move(logpath, logpath_moved)
+    l1.daemon.proc.send_signal(signal.SIGHUP)
+    wait_for(lambda: os.path.exists(logpath_moved))
+    wait_for(lambda: os.path.exists(logpath))
+
+    log1 = open(logpath_moved).readlines()
+    log2 = open(logpath).readlines()
+
+    assert log1[-1].endswith("Ending log due to SIGHUP\n")
+    assert log2[0].endswith("Started log due to SIGHUP\n")
+
+
+@unittest.skipIf(VALGRIND and not DEVELOPER,
+                 "Backtrace upsets valgrind: only suppressed in DEVELOPER mode")
+def test_crashlog(node_factory):
+    l1 = node_factory.get_node(may_fail=True)
+
+    def has_crash_log(n):
+        files = os.listdir(n.daemon.lightning_dir)
+        crashfiles = [f for f in files if 'crash.log' in f]
+        return len(crashfiles) > 0
+
+    assert not has_crash_log(l1)
+    l1.daemon.proc.send_signal(signal.SIGSEGV)
+    wait_for(lambda: has_crash_log(l1))