lightningd: log entry allocation and getlog output (v26.06.7 security, 5/7)

contrib/msggen/msggen/schema.json

@@ -16679,11 +16679,10 @@
               "unusual",
               "info",
               "debug",
-              "trace",
-              "io"
+              "trace"
             ],
             "description": [
-              "A string that represents the log level."
+              "A string that represents the log level. Note that *io* is not accepted here: the io log contains raw JSON-RPC and plugin traffic (including runes and other secrets), so it is only available in the log file, via *log-level=io*."
             ],
             "default": "*info*"
           }

contrib/pyln-client/pyln/client/lightning.py

@@ -856,7 +856,7 @@ def getinfo(self):
 
     def getlog(self, level=None):
         """
-        Show logs, with optional log {level} (info|unusual|debug|io).
+        Show logs, with optional log {level} (info|unusual|debug|trace).
         """
         payload = {
             "level": level

doc/schemas/getlog.json

@@ -20,11 +20,10 @@
           "unusual",
           "info",
           "debug",
-          "trace",
-          "io"
+          "trace"
         ],
         "description": [
-          "A string that represents the log level."
+          "A string that represents the log level. Note that *io* is not accepted here: the io log contains raw JSON-RPC and plugin traffic (including runes and other secrets), so it is only available in the log file, via *log-level=io*."
         ],
         "default": "*info*"
       }

lightningd/log.c

@@ -394,15 +394,24 @@ static void log_to_files(const char *log_prefix,
 {
 	char tstamp[sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ ")];
 	char *entry, nodestr[hex_str_size(PUBKEY_CMPR_LEN)];
-	char buf[sizeof("%s%s%s %s-%s: %s\n")
+	/* Entries are usually small, so a stack buffer is fine; but a
+	 * peer can make us log arbitrarily large strings (e.g. clnrest
+	 * logging unauthenticated request parameters), which must not
+	 * be allocated on the stack! */
+	char sbuf[1024];
+	char *buf = sbuf;
+	size_t buf_len = sizeof("%s%s%s %s-%s: %s\n")
 		 + strlen(log_prefix)
 		 + sizeof(tstamp)
 		 + strlen(level_prefix(level))
 		 + sizeof(nodestr)
 		 + strlen(entry_prefix)
-		 + str_len];
+		 + str_len;
 	bool filtered;
 
+	if (buf_len > sizeof(sbuf))
+		buf = tal_arr(tmpctx, char, buf_len);
+
 	if (print_timestamps) {
 		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));
@@ -431,15 +440,15 @@ static void log_to_files(const char *log_prefix,
 		size_t len;
 		entry = buf;
 		if (!node_id)
-			len = snprintf(buf, sizeof(buf),
+			len = snprintf(buf, buf_len,
 				       "%s%s%s %s: %.*s\n",
 				       log_prefix, tstamp, level_prefix(level), entry_prefix, (int)str_len, str);
 		else
-			len = snprintf(buf, sizeof(buf), "%s%s%s %s-%s: %.*s\n",
+			len = snprintf(buf, buf_len, "%s%s%s %s-%s: %.*s\n",
 				       log_prefix, tstamp, level_prefix(level),
 				       nodestr,
 				       entry_prefix, (int)str_len, str);
-		assert(len < sizeof(buf));
+		assert(len < buf_len);
 	}
 
 	/* In complex configurations, we tell loggers to overshare: then we
@@ -1223,6 +1232,30 @@ struct command_result *param_loglevel(struct command *cmd,
 				     "'unusual'");
 }
 
+/* The io log contains raw JSON-RPC and plugin traffic, which can contain
+ * secrets (such as runes), and getlog returns the entire log book: so we
+ * don't serve io here.  It's still available in the log file, for those who
+ * run with --log-level=io. */
+static struct command_result *param_getloglevel(struct command *cmd,
+						const char *name,
+						const char *buffer,
+						const jsmntok_t *tok,
+						enum log_level **level)
+{
+	struct command_result *ret;
+
+	ret = param_loglevel(cmd, name, buffer, tok, level);
+	if (ret)
+		return ret;
+
+	if (**level == LOG_IO_IN || **level == LOG_IO_OUT)
+		return command_fail_badparam(cmd, name, buffer, tok,
+					     "io logs are not available here:"
+					     " use --log-level=io and read the"
+					     " log file");
+	return NULL;
+}
+
 static struct command_result *json_getlog(struct command *cmd,
 					  const char *buffer,
 					  const jsmntok_t *obj UNNEEDED,
@@ -1233,7 +1266,7 @@ static struct command_result *json_getlog(struct command *cmd,
 	struct log_book *log_book = cmd->ld->log_book;
 
 	if (!param(cmd, buffer, params,
-		   p_opt_def("level", param_loglevel, &minlevel, LOG_INFORM),
+		   p_opt_def("level", param_getloglevel, &minlevel, LOG_INFORM),
 		   NULL))
 		return command_param_failed();
 

tests/plugins/hugelog.py

@@ -0,0 +1,22 @@
+#!/usr/bin/env python3
+"""Plugin which emits a single log entry of an arbitrary size.
+
+A log entry is not bounded by anything the daemon controls: a plugin can
+hand us a message of any length, and so can any subsystem which logs
+attacker-influenced data.  This gives a test a direct way to drive
+log_to_files() with an entry far larger than any stack buffer.
+"""
+from pyln.client import Plugin
+
+plugin = Plugin()
+
+
+@plugin.method("hugelog")
+def hugelog(plugin, bytelen):
+    """Log one entry of bytelen bytes, on a single line."""
+    bytelen = int(bytelen)
+    plugin.log("X" * bytelen)
+    return {"logged": bytelen}
+
+
+plugin.run()

tests/test_misc.py

@@ -3895,8 +3895,28 @@ def test_getlog(node_factory):
     logs = l1.rpc.getlog()['log']
     assert [l for l in logs if l['type'] not in ("BROKEN", "UNUSUAL", "INFO")] == []
 
-    logs = l1.rpc.getlog(level='io')['log']
-    assert [l for l in logs if l['type'] not in ("BROKEN", "UNUSUAL", "INFO", "DEBUG", "TRACE", "IO_IN", "IO_OUT")] == []
+    logs = l1.rpc.getlog(level='trace')['log']
+    assert [l for l in logs if l['type'] not in ("BROKEN", "UNUSUAL", "INFO", "DEBUG", "TRACE")] == []
+
+
+def test_getlog_no_io(node_factory):
+    """getlog must not hand out io logs: they contain the raw JSON-RPC and
+    plugin traffic, which includes secrets such as runes."""
+    l1 = node_factory.get_node(options={'log-level': 'io'})
+
+    rune = l1.rpc.createrune()['rune']
+
+    # The schema doesn't allow it, but lightningd must refuse it too.
+    l1.rpc.check_request_schemas = False
+    with pytest.raises(RpcError, match='io logs are not available'):
+        l1.rpc.getlog(level='io')
+    l1.rpc.check_request_schemas = True
+
+    # Nor do the other levels expose raw traffic.
+    for level in ('trace', 'debug', 'info', 'unusual', 'broken'):
+        for entry in l1.rpc.getlog(level=level)['log']:
+            assert 'data' not in entry
+            assert rune not in entry.get('log', '')
 
 
 def test_log_filter(node_factory):

tests/test_plugin.py

@@ -3372,11 +3372,12 @@ def test_commando(node_factory, executor):
     assert 'totlen' in ret
 
     # Now, reply will go over a multiple messages!
+    l1.rpc.datastore(key='bigstring', string='X' * 100000)
     ret = l2.rpc.call(method='commando',
                       payload={'peer_id': l1.info['id'],
                                'rune': rune,
-                               'method': 'getlog',
-                               'params': {'level': 'io'}})
+                               'method': 'listdatastore',
+                               'params': {'key': 'bigstring'}})
 
     assert len(json.dumps(ret)) > 65535
 
@@ -6271,3 +6272,20 @@ def on_mymethod(plugin):
         l1.rpc.plugin_start(
             plugin=os.path.join(os.getcwd(), "tests/plugins/builtin_collision.py")
         )
+
+
+def test_huge_log_entry(node_factory):
+    """A single log entry larger than any stack buffer must not crash us.
+
+    log_to_files() used to size its buffer with a variable-length array
+    derived from the entry length, so a caller which could influence that
+    length could run the stack out.  Nothing bounds an entry: a plugin can
+    hand us one of any size, which is what this drives.
+    """
+    plugin_path = os.path.join(os.getcwd(), 'tests/plugins/hugelog.py')
+    l1 = node_factory.get_node(options={'plugin': plugin_path})
+
+    assert l1.rpc.call('hugelog', {'bytelen': 8 * 1024 * 1024})['logged'] == 8 * 1024 * 1024
+
+    # Still alive, and still answering.
+    assert l1.rpc.getinfo()['id'] == l1.info['id']