lightningd: don't log JSON ids as debug, use log io.

They are cute, sure, but they do spam the logs.

@Suggested-by: @niftynei
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd/jsonrpc.c

@@ -912,7 +912,9 @@ parse_request(struct json_connection *jcon, const jsmntok_t tok[])
 				    "Expected string for method");
 	}
 
-	log_debug(jcon->log, "IN:id=%s", c->id);
+	/* Debug was too chatty, so we use IO here, even though we're
+	 * actually just logging the id */
+	log_io(jcon->log, LOG_IO_IN, NULL, c->id, NULL, 0);
 
 	c->json_cmd = find_cmd(jcon->ld->jsonrpc, jcon->buffer, method);
 	if (!c->json_cmd) {
@@ -1353,7 +1355,7 @@ struct jsonrpc_request *jsonrpc_request_start_(
 		json_object_start(r->stream, "params");
 	}
 	if (log)
-		log_debug(log, "OUT:id=%s", r->id);
+		log_io(log, LOG_IO_OUT, NULL, r->id, NULL, 0);
 
 	return r;
 }

tests/test_invoices.py

@@ -12,7 +12,7 @@ import unittest
 
 
 def test_invoice(node_factory, chainparams):
-    l1, l2 = node_factory.line_graph(2, fundchannel=False)
+    l1, l2 = node_factory.line_graph(2, fundchannel=False, opts={'log-level': 'io'})
 
     addr1 = l2.rpc.newaddr('bech32')['bech32']
     addr2 = l2.rpc.newaddr('p2sh-segwit')['p2sh-segwit']
@@ -21,7 +21,7 @@ def test_invoice(node_factory, chainparams):
 
     # Side note: invoice calls out to listincoming, so check JSON id is as expected
     myname = os.path.splitext(os.path.basename(sys.argv[0]))[0]
-    l1.daemon.wait_for_log(": OUT:id={}:invoice#[0-9]*/cln:listincoming#[0-9]*".format(myname))
+    l1.daemon.wait_for_log(r": {}:invoice#[0-9]*/cln:listincoming#[0-9]*\[OUT\]".format(myname))
 
     after = int(time.time())
     b11 = l1.rpc.decodepay(inv['bolt11'])

tests/test_misc.py

@@ -863,7 +863,7 @@ def test_malformed_rpc(node_factory):
 
 
 def test_cli(node_factory):
-    l1 = node_factory.get_node()
+    l1 = node_factory.get_node(options={'log-level': 'io'})
 
     out = subprocess.check_output(['cli/lightning-cli',
                                    '--network={}'.format(TEST_NETWORK),
@@ -874,7 +874,7 @@ def test_cli(node_factory):
     assert 'help [command]\n    List available commands, or give verbose help on one {command}' in out
 
     # Check JSON id is as expected
-    l1.daemon.wait_for_log("jsonrpc#[0-9]*: IN:id=cli:help#[0-9]*")
+    l1.daemon.wait_for_log(r"jsonrpc#[0-9]*: cli:help#[0-9]*\[IN\]")
 
     # Test JSON output.
     out = subprocess.check_output(['cli/lightning-cli',

tests/test_plugin.py

@@ -1478,7 +1478,8 @@ def test_libplugin(node_factory):
     """Sanity checks for plugins made with libplugin"""
     plugin = os.path.join(os.getcwd(), "tests/plugins/test_libplugin")
     l1 = node_factory.get_node(options={"plugin": plugin,
-                                        'allow-deprecated-apis': False})
+                                        'allow-deprecated-apis': False,
+                                        'log-level': 'io'})
 
     # Test startup
     assert l1.daemon.is_in_log("test_libplugin initialised!")
@@ -1490,7 +1491,7 @@ def test_libplugin(node_factory):
     myname = os.path.splitext(os.path.basename(sys.argv[0]))[0]
 
     # Side note: getmanifest will trace back to plugin_start
-    l1.daemon.wait_for_log(": OUT:id={}:plugin#[0-9]*/cln:getmanifest#[0-9]*".format(myname))
+    l1.daemon.wait_for_log(r": {}:plugin#[0-9]*/cln:getmanifest#[0-9]*\[OUT\]".format(myname))
 
     # Test commands
     assert l1.rpc.call("helloworld") == {"hello": "world"}
@@ -1504,9 +1505,9 @@ def test_libplugin(node_factory):
     assert l1.rpc.call("helloworld", {"name": "test"}) == {"hello": "test"}
 
     # Test hooks and notifications (add plugin, so we can test hook id)
-    l2 = node_factory.get_node(options={"plugin": plugin})
+    l2 = node_factory.get_node(options={"plugin": plugin, 'log-level': 'io'})
     l2.connect(l1)
-    l2.daemon.wait_for_log(": OUT:id={}:connect#[0-9]*/cln:peer_connected#[0-9]*".format(myname))
+    l2.daemon.wait_for_log(r": {}:connect#[0-9]*/cln:peer_connected#[0-9]*\[OUT\]".format(myname))
 
     l1.daemon.wait_for_log("{} peer_connected".format(l2.info["id"]))
     l1.daemon.wait_for_log("{} connected".format(l2.info["id"]))

tests/test_wallet.py

@@ -29,7 +29,7 @@ HSM_BAD_PASSWORD = 22
 def test_withdraw(node_factory, bitcoind):
     amount = 1000000
     # Don't get any funds from previous runs.
-    l1 = node_factory.get_node(random_hsm=True)
+    l1 = node_factory.get_node(random_hsm=True, options={'log-level': 'io'})
     l2 = node_factory.get_node(random_hsm=True)
     addr = l1.rpc.newaddr()['bech32']
 
@@ -62,7 +62,7 @@ def test_withdraw(node_factory, bitcoind):
 
     # Side note: sendrawtransaction will trace back to withdrawl
     myname = os.path.splitext(os.path.basename(sys.argv[0]))[0]
-    l1.daemon.wait_for_log(": OUT:id={}:withdraw#[0-9]*/cln:withdraw#[0-9]*/txprepare:sendpsbt#[0-9]*/cln:sendrawtransaction#[0-9]*".format(myname))
+    l1.daemon.wait_for_log(r": {}:withdraw#[0-9]*/cln:withdraw#[0-9]*/txprepare:sendpsbt#[0-9]*/cln:sendrawtransaction#[0-9]*\[OUT\]".format(myname))
 
     # Make sure bitcoind received the withdrawal
     unspent = l1.bitcoin.rpc.listunspent(0)