From d2952576cd3ed95c3b2157ece0ae597add200fbb Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Sun, 26 Jun 2022 14:13:01 +0930 Subject: [PATCH] pyln-testing: restore proper streaming behaviour for lightningd. Get it to log direct to stdout, so we see what's happening *as it happens* rather than as we read it. We could restore the thread we were using before, but that added more problems than it solved. This means that we need the hsm password prompts in the log though. Signed-off-by: Rusty Russell --- contrib/pyln-testing/pyln/testing/utils.py | 34 +++++++++++++++------- lightningd/options.c | 23 ++++++++++----- tests/test_misc.py | 10 +++++-- 3 files changed, 47 insertions(+), 20 deletions(-) diff --git a/contrib/pyln-testing/pyln/testing/utils.py b/contrib/pyln-testing/pyln/testing/utils.py index 62d650cb3..590097b0f 100644 --- a/contrib/pyln-testing/pyln/testing/utils.py +++ b/contrib/pyln-testing/pyln/testing/utils.py @@ -199,15 +199,24 @@ class TailableProc(object): # pass it to the log matcher and not print it to stdout). self.log_filter = lambda line: False - def start(self, stdin=None): - """Start the underlying process and start monitoring it. + def start(self, stdin=None, stdout_redir=True): + """Start the underlying process and start monitoring it. If + stdout_redir is false, you have to make sure logs go into + outputDir/log + """ logging.debug("Starting '%s'", " ".join(self.cmd_line)) - self.proc = subprocess.Popen(self.cmd_line, - stdin=stdin, - stdout=self.stdout_write, - stderr=self.stderr_write, - env=self.env) + if stdout_redir: + self.proc = subprocess.Popen(self.cmd_line, + stdin=stdin, + stdout=self.stdout_write, + stderr=self.stderr_write, + env=self.env) + else: + self.proc = subprocess.Popen(self.cmd_line, + stdin=stdin, + stderr=self.stderr_write, + env=self.env) def stop(self, timeout=10): self.proc.terminate() @@ -529,7 +538,8 @@ class ElementsD(BitcoinD): class LightningD(TailableProc): def __init__(self, lightning_dir, bitcoindproxy, port=9735, random_hsm=False, node_id=0): - TailableProc.__init__(self, lightning_dir) + # We handle our own version of verbose, below. + TailableProc.__init__(self, lightning_dir, verbose=False) self.executable = 'lightningd' self.lightning_dir = lightning_dir self.port = port @@ -568,6 +578,10 @@ class LightningD(TailableProc): self.opts['dev-fast-gossip'] = None self.opts['dev-bitcoind-poll'] = 1 self.prefix = 'lightningd-%d' % (node_id) + # Log to stdout so we see it in failure cases, and log file for TailableProc. + self.opts['log-file'] = ['-', os.path.join(lightning_dir, "log")] + # In case you want specific ordering! + self.early_opts = [] def cleanup(self): # To force blackhole to exit, disconnect file must be truncated! @@ -588,11 +602,11 @@ class LightningD(TailableProc): else: opts.append("--{}={}".format(k, v)) - return self.cmd_prefix + [self.executable] + opts + return self.cmd_prefix + [self.executable] + self.early_opts + opts def start(self, stdin=None, wait_for_initialized=True): self.opts['bitcoin-rpcport'] = self.rpcproxy.rpcport - TailableProc.start(self, stdin) + TailableProc.start(self, stdin, stdout_redir=False) if wait_for_initialized: self.wait_for_log("Server started with public key") logging.info("LightningD started") diff --git a/lightningd/options.c b/lightningd/options.c index e7e2b9cc4..2af57ac09 100644 --- a/lightningd/options.c +++ b/lightningd/options.c @@ -493,6 +493,16 @@ static char *opt_important_plugin(const char *arg, struct lightningd *ld) return NULL; } +/* Test code looks in logs, so we print prompts to log as well as stdout */ +static void prompt(struct lightningd *ld, const char *str) +{ + printf("%s\n", str); + log_debug(ld->log, "PROMPT: %s", str); + /* If we don't flush we might end up being buffered and we might seem + * to hang while we wait for the password. */ + fflush(stdout); +} + /* Prompt the user to enter a password, from which will be derived the key used * for `hsm_secret` encryption. * The algorithm used to derive the key is Argon2(id), to which libsodium @@ -509,18 +519,15 @@ static char *opt_set_hsm_password(struct lightningd *ld) return tal_fmt(NULL, "Could not access 'hsm_secret': %s", strerror(errno)); - printf("The hsm_secret is encrypted with a password. In order to " - "decrypt it and start the node you must provide the password.\n"); - printf("Enter hsm_secret password:\n"); - /* If we don't flush we might end up being buffered and we might seem - * to hang while we wait for the password. */ - fflush(stdout); + prompt(ld, "The hsm_secret is encrypted with a password. In order to " + "decrypt it and start the node you must provide the password."); + prompt(ld, "Enter hsm_secret password:"); passwd = read_stdin_pass_with_exit_code(&err_msg, &opt_exitcode); if (!passwd) return err_msg; if (!is_encrypted) { - printf("Confirm hsm_secret password:\n"); + prompt(ld, "Confirm hsm_secret password:"); fflush(stdout); passwd_confirmation = read_stdin_pass_with_exit_code(&err_msg, &opt_exitcode); if (!passwd_confirmation) @@ -532,7 +539,7 @@ static char *opt_set_hsm_password(struct lightningd *ld) } free(passwd_confirmation); } - printf("\n"); + prompt(ld, ""); ld->config.keypass = tal(NULL, struct secret); diff --git a/tests/test_misc.py b/tests/test_misc.py index d209778af..e6bf96c8e 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -1007,8 +1007,11 @@ def test_daemon_option(node_factory): l1.stop() os.unlink(l1.rpc.socket_path) + # Stop it from logging to stdout! logfname = os.path.join(l1.daemon.lightning_dir, TEST_NETWORK, "log-daemon") - subprocess.run(l1.daemon.cmd_line + ['--daemon', '--log-file={}'.format(logfname)], env=l1.daemon.env, + l1.daemon.opts['log-file'] = logfname + l1.daemon.opts['daemon'] = None + subprocess.run(l1.daemon.cmd_line, env=l1.daemon.env, check=True) # Test some known output (wait for rpc to be ready) @@ -2399,7 +2402,10 @@ def test_version_reexec(node_factory, bitcoind): def test_notimestamp_logging(node_factory): - l1 = node_factory.get_node(options={'log-timestamps': False}) + l1 = node_factory.get_node(start=False) + # Make sure this is specified *before* other options! + l1.daemon.early_opts = ['--log-timestamps=false'] + l1.start() assert l1.daemon.logs[0].startswith("DEBUG") assert l1.rpc.listconfigs()['log-timestamps'] is False