From 54ce4ed1cf4007ac8754c5bb640c4afdbdbc3934 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Sun, 30 Jun 2019 10:12:44 +0930 Subject: [PATCH] pytest: fail tests if we get any LOG_BROKEN level messages, unless flagged. And clean up some dev ones which actually happen (mainly by calling channel_fail_permanent which logs UNUSUAL, rather than channel_internal_error which logs BROKEN). Signed-off-by: Rusty Russell --- channeld/full_channel.c | 6 +++--- common/crypto_sync.c | 6 +++--- lightningd/channel.c | 2 +- lightningd/peer_control.c | 4 ++-- tests/fixtures.py | 11 +++++++++++ tests/test_closing.py | 4 ++-- tests/test_connection.py | 2 +- tests/test_gossip.py | 4 ++-- tests/test_misc.py | 2 +- tests/test_plugin.py | 2 +- tests/utils.py | 8 +++++--- 11 files changed, 32 insertions(+), 19 deletions(-) diff --git a/channeld/full_channel.c b/channeld/full_channel.c index 7dce4521c..c030af787 100644 --- a/channeld/full_channel.c +++ b/channeld/full_channel.c @@ -314,10 +314,10 @@ static bool get_room_above_reserve(const struct channel *channel, for (size_t i = 0; i < tal_count(adding); i++) ok &= balance_add_htlc(balance, adding[i], side); - /* Overflow shouldn't happen, but if it does, complain */ + /* Can happen if amount completely exceeds capacity */ if (!ok) { - status_broken("Failed to add %zu remove %zu htlcs", - tal_count(adding), tal_count(removing)); + status_trace("Failed to add %zu remove %zu htlcs", + tal_count(adding), tal_count(removing)); return false; } diff --git a/common/crypto_sync.c b/common/crypto_sync.c index 2bea9b203..723bb655b 100644 --- a/common/crypto_sync.c +++ b/common/crypto_sync.c @@ -85,9 +85,9 @@ void sync_crypto_write_no_delay(struct per_peer_state *pps, if (setsockopt(pps->peer_fd, IPPROTO_TCP, opt, &val, sizeof(val)) != 0) { /* This actually happens in testing, where we blackhole the fd */ if (!complained) { - status_broken("setsockopt %s=1: %s", - optname, - strerror(errno)); + status_unusual("setsockopt %s=1: %s", + optname, + strerror(errno)); complained = true; } } diff --git a/lightningd/channel.c b/lightningd/channel.c index 64b8cfa60..3a29f3930 100644 --- a/lightningd/channel.c +++ b/lightningd/channel.c @@ -441,7 +441,7 @@ void channel_fail_transient(struct channel *channel, const char *fmt, ...) #if DEVELOPER if (dev_disconnect_permanent(channel->peer->ld)) { - channel_internal_error(channel, "dev_disconnect permfail"); + channel_fail_permanent(channel, "dev_disconnect permfail"); return; } #endif diff --git a/lightningd/peer_control.c b/lightningd/peer_control.c index 7315e4501..13b7f4400 100644 --- a/lightningd/peer_control.c +++ b/lightningd/peer_control.c @@ -830,7 +830,7 @@ peer_connected_hook_cb(struct peer_connected_hook_payload *payload, #if DEVELOPER if (dev_disconnect_permanent(ld)) { - channel_internal_error(channel, + channel_fail_permanent(channel, "dev_disconnect permfail"); error = channel->error; goto send_error; @@ -1698,7 +1698,7 @@ static struct command_result *json_dev_fail(struct command *cmd, "Could not find active channel with peer"); } - channel_internal_error(channel, "Failing due to dev-fail command"); + channel_fail_permanent(channel, "Failing due to dev-fail command"); return command_success(cmd, json_stream_success(cmd)); } diff --git a/tests/fixtures.py b/tests/fixtures.py index 8d914ee17..bcd88a705 100644 --- a/tests/fixtures.py +++ b/tests/fixtures.py @@ -127,6 +127,10 @@ def node_factory(request, directory, test_name, bitcoind, executor): err_count += printCrashLog(node) check_errors(request, err_count, "{} nodes had crash.log files") + for node in [n for n in nf.nodes if not n.allow_broken_log]: + err_count += checkBroken(node) + check_errors(request, err_count, "{} nodes had BROKEN messages") + for node in nf.nodes: err_count += checkReconnect(node) check_errors(request, err_count, "{} nodes had unexpected reconnections") @@ -219,6 +223,13 @@ def checkBadGossip(node): return 0 +def checkBroken(node): + # We can get bad gossip order from inside error msgs. + if node.daemon.is_in_log(r'\*\*BROKEN\*\*'): + return 1 + return 0 + + def checkBadReestablish(node): if node.daemon.is_in_log('Bad reestablish'): return 1 diff --git a/tests/test_closing.py b/tests/test_closing.py index 1d8753eeb..894875d74 100644 --- a/tests/test_closing.py +++ b/tests/test_closing.py @@ -296,7 +296,7 @@ def test_penalty_inhtlc(node_factory, bitcoind, executor): """Test penalty transaction with an incoming HTLC""" # We suppress each one after first commit; HTLC gets added not fulfilled. # Feerates identical so we don't get gratuitous commit to update them - l1 = node_factory.get_node(disconnect=['=WIRE_COMMITMENT_SIGNED-nocommit'], may_fail=True, feerates=(7500, 7500, 7500)) + l1 = node_factory.get_node(disconnect=['=WIRE_COMMITMENT_SIGNED-nocommit'], may_fail=True, feerates=(7500, 7500, 7500), allow_broken_log=True) l2 = node_factory.get_node(disconnect=['=WIRE_COMMITMENT_SIGNED-nocommit']) l1.rpc.connect(l2.info['id'], 'localhost', l2.port) @@ -368,7 +368,7 @@ def test_penalty_outhtlc(node_factory, bitcoind, executor): """Test penalty transaction with an outgoing HTLC""" # First we need to get funds to l2, so suppress after second. # Feerates identical so we don't get gratuitous commit to update them - l1 = node_factory.get_node(disconnect=['=WIRE_COMMITMENT_SIGNED*3-nocommit'], may_fail=True, feerates=(7500, 7500, 7500)) + l1 = node_factory.get_node(disconnect=['=WIRE_COMMITMENT_SIGNED*3-nocommit'], may_fail=True, feerates=(7500, 7500, 7500), allow_broken_log=True) l2 = node_factory.get_node(disconnect=['=WIRE_COMMITMENT_SIGNED*3-nocommit']) l1.rpc.connect(l2.info['id'], 'localhost', l2.port) diff --git a/tests/test_connection.py b/tests/test_connection.py index dd6dd9e5b..0c24e2be4 100644 --- a/tests/test_connection.py +++ b/tests/test_connection.py @@ -1490,7 +1490,7 @@ def test_dataloss_protection(node_factory, bitcoind): l1 = node_factory.get_node(may_reconnect=True, log_all_io=True, feerates=(7500, 7500, 7500)) l2 = node_factory.get_node(may_reconnect=True, log_all_io=True, - feerates=(7500, 7500, 7500)) + feerates=(7500, 7500, 7500), allow_broken_log=True) l1.rpc.connect(l2.info['id'], 'localhost', l2.port) # l1 should send out WIRE_INIT (0010) diff --git a/tests/test_gossip.py b/tests/test_gossip.py index 79ad9228a..45663da8e 100644 --- a/tests/test_gossip.py +++ b/tests/test_gossip.py @@ -934,7 +934,7 @@ def test_gossip_store_load_announce_before_update(node_factory): def test_gossip_store_load_amount_truncated(node_factory): """Make sure we can read canned gossip store with truncated amount""" - l1 = node_factory.get_node(start=False) + l1 = node_factory.get_node(start=False, allow_broken_log=True) with open(os.path.join(l1.daemon.lightning_dir, 'gossip_store'), 'wb') as f: f.write(bytearray.fromhex("07" # GOSSIP_STORE_VERSION "000001b0" # len @@ -1251,7 +1251,7 @@ def test_gossip_store_compact_restart(node_factory, bitcoind): @unittest.skipIf(not DEVELOPER, "need dev-compact-gossip-store") def test_gossip_store_load_no_channel_update(node_factory): """Make sure we can read truncated gossip store with a channel_announcement and no channel_update""" - l1 = node_factory.get_node(start=False) + l1 = node_factory.get_node(start=False, allow_broken_log=True) # A channel announcement with no channel_update. with open(os.path.join(l1.daemon.lightning_dir, 'gossip_store'), 'wb') as f: diff --git a/tests/test_misc.py b/tests/test_misc.py index 06915f5b0..b0235bf53 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -1044,7 +1044,7 @@ def test_logging(node_factory): @unittest.skipIf(VALGRIND, "Valgrind sometimes fails assert on injected SEGV") def test_crashlog(node_factory): - l1 = node_factory.get_node(may_fail=True) + l1 = node_factory.get_node(may_fail=True, allow_broken_log=True) def has_crash_log(n): files = os.listdir(n.daemon.lightning_dir) diff --git a/tests/test_plugin.py b/tests/test_plugin.py index fdbf1c86f..7a68df658 100644 --- a/tests/test_plugin.py +++ b/tests/test_plugin.py @@ -435,7 +435,7 @@ def test_htlc_accepted_hook_forward_restart(node_factory, executor): def test_warning_notification(node_factory): """ test 'warning' notifications """ - l1 = node_factory.get_node(options={'plugin': 'tests/plugins/pretend_badlog.py'}) + l1 = node_factory.get_node(options={'plugin': 'tests/plugins/pretend_badlog.py'}, allow_broken_log=True) # 1. test 'warn' level event = "Test warning notification(for unusual event)" diff --git a/tests/utils.py b/tests/utils.py index 02ea9cd2b..b4f84d1e2 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -454,13 +454,14 @@ class LightningD(TailableProc): class LightningNode(object): - def __init__(self, daemon, rpc, btc, executor, may_fail=False, may_reconnect=False): + def __init__(self, daemon, rpc, btc, executor, may_fail=False, may_reconnect=False, allow_broken_log=False): self.rpc = rpc self.daemon = daemon self.bitcoin = btc self.executor = executor self.may_fail = may_fail self.may_reconnect = may_reconnect + self.allow_broken_log = allow_broken_log def connect(self, remote_node): self.rpc.connect(remote_node.info['id'], '127.0.0.1', remote_node.daemon.port) @@ -773,6 +774,7 @@ class NodeFactory(object): node_opt_keys = [ 'disconnect', 'may_fail', + 'allow_broken_log', 'may_reconnect', 'random_hsm', 'log_all_io', @@ -819,7 +821,7 @@ class NodeFactory(object): def get_node(self, disconnect=None, options=None, may_fail=False, may_reconnect=False, random_hsm=False, feerates=(15000, 7500, 3750), start=True, log_all_io=False, - dbfile=None, node_id=None): + dbfile=None, node_id=None, allow_broken_log=False): if not node_id: node_id = self.get_node_id() @@ -862,7 +864,7 @@ class NodeFactory(object): rpc = LightningRpc(socket_path, self.executor) node = LightningNode(daemon, rpc, self.bitcoind, self.executor, may_fail=may_fail, - may_reconnect=may_reconnect) + may_reconnect=may_reconnect, allow_broken_log=allow_broken_log) # Regtest estimatefee are unusable, so override. node.set_feerates(feerates, False)