log: implement reopening log-file on SIGHUP

Closes: #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,6 +446,59 @@ 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;
@@ -451,7 +506,9 @@ char *arg_log_to_file(const char *arg, struct lightningd *ld)
 	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)

tests/test_misc.py

@@ -2,12 +2,13 @@ from decimal import Decimal
 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, 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,24 @@ 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")