log: implement reopening log-file on SIGHUP

Closes: ElementsProject#1623
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

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
 

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,67 @@ 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)
+{
+	/* 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)
@@ -686,3 +741,4 @@ static const struct json_command getlog_command = {
 	"Show logs, with optional log {level} (info|unusual|debug|io)"
 };
 AUTODATA(json_command, &getlog_command);
+

tests/fixtures.py

@@ -56,7 +56,7 @@ def directory(request, test_base_dir, test_name):
     # This uses the status set in conftest.pytest_runtest_makereport to
     # determine whether we succeeded or failed.
     if request.node.rep_call.outcome == 'passed':
-        shutil.rmtree(directory)
+        pass #shutil.rmtree(directory)
     else:
         logging.debug("Test execution failed, leaving the test directory {} intact.".format(directory))
 

tests/test_misc.py

@@ -8,6 +8,7 @@
 import json
 import os
 import pytest
+import shutil
 import signal
 import socket
 import subprocess
@@ -846,3 +847,25 @@ 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')
+
+    # FIXME: I couldn't get super(TailableProc, l1.daemon).start() to work?
+    l1.daemon.raw_start()
+    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")

tests/utils.py

@@ -351,6 +351,10 @@ def cmd_line(self):
 
         return self.cmd_prefix + ['lightningd/lightningd'] + opts
 
+    # There should be a way to access this with super(), but I can't figure it
+    def raw_start(self):
+        TailableProc.start(self)
+
     def start(self):
         TailableProc.start(self)
         self.wait_for_log("Server started with public key")