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 <rusty@rustcorp.com.au>

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;
 	}
 

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;
 		}
 	}

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

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));
 }
 

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

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)

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)

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:

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)

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)"

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)