Flaky fixes

.github/workflows/ci.yaml

@@ -16,7 +16,7 @@ env:
   RUST_PROFILE: release
   SLOW_MACHINE: 1
   CI_SERVER_URL: "http://35.239.136.52:3170"
-  PYTEST_OPTS_BASE: "--reruns=10 -vvv --junit-xml=report.xml --timeout=1800 --durations=10"
+  PYTEST_OPTS_BASE: "-vvv --junit-xml=report.xml --timeout=1800 --durations=10"
 
 jobs:
   prebuild:
@@ -337,7 +337,7 @@ jobs:
     timeout-minutes: 120
     env:
       RUST_PROFILE: release # Has to match the one in the compile step
-      PYTEST_OPTS: --reruns=10 -vvv --junit-xml=report.xml --timeout=1800 --durations=10
+      PYTEST_OPTS: -vvv --junit-xml=report.xml --timeout=1800 --durations=10
     needs:
       - compile
     strategy:
@@ -453,7 +453,7 @@ jobs:
     env:
       RUST_PROFILE: release # Has to match the one in the compile step
       CFG: compile-gcc
-      PYTEST_OPTS: --reruns=10 -vvv --junit-xml=report.xml --timeout=1800 --durations=10 --test-group-random-seed=42
+      PYTEST_OPTS: -vvv --junit-xml=report.xml --timeout=1800 --durations=10 --test-group-random-seed=42
     needs:
       - compile
     strategy:
@@ -541,7 +541,7 @@ jobs:
       RUST_PROFILE: release
       SLOW_MACHINE: 1
       TEST_DEBUG: 1
-      PYTEST_OPTS: --reruns=10 -vvv --junit-xml=report.xml --timeout=1800 --durations=10 --test-group-random-seed=42 
+      PYTEST_OPTS: -vvv --junit-xml=report.xml --timeout=1800 --durations=10 --test-group-random-seed=42 
     needs:
       - compile
     strategy:
@@ -553,7 +553,7 @@ jobs:
             PYTEST_OPTS: --test-group=1  --test-group-count=12
           - NAME: ASan/UBSan (02/12)
             GROUP: 2
-            PYTEST_OPTS: --test-group=2  --test-group-count=12 -n 1
+            PYTEST_OPTS: --test-group=2  --test-group-count=12
           - NAME: ASan/UBSan (03/12)
             GROUP: 3
             PYTEST_OPTS: --test-group=3  --test-group-count=12
@@ -632,7 +632,7 @@ jobs:
     env:
       VALGRIND: 0
       GENERATE_EXAMPLES: 1
-      PYTEST_OPTS: --reruns=10 -vvv --junit-xml=report.xml --timeout=1800 --durations=10
+      PYTEST_OPTS: -vvv --junit-xml=report.xml --timeout=1800 --durations=10
       TEST_NETWORK: regtest
     needs:
       - compile
@@ -678,7 +678,7 @@ jobs:
     timeout-minutes: 120
     env:
       RUST_PROFILE: release # Has to match the one in the compile step
-      PYTEST_OPTS: --reruns=10 -vvv --junit-xml=report.xml --timeout=1800 --durations=10
+      PYTEST_OPTS: -vvv --junit-xml=report.xml --timeout=1800 --durations=10
     needs:
       - compile
     strategy:

contrib/pyln-testing/pyln/testing/fixtures.py

@@ -498,7 +498,7 @@ def map_node_error(nodes, f, msg):
 
     map_node_error(nf.nodes, printValgrindErrors, "reported valgrind errors")
     map_node_error(nf.nodes, printCrashLog, "had crash.log files")
-    map_node_error(nf.nodes, checkBroken, "had BROKEN messages")
+    map_node_error(nf.nodes, checkBroken, "had BROKEN or That's weird messages")
     map_node_error(nf.nodes, lambda n: not n.allow_warning and n.daemon.is_in_log(r' WARNING:'), "had warning messages")
     map_node_error(nf.nodes, checkReconnect, "had unexpected reconnections")
     map_node_error(nf.nodes, checkPluginJSON, "had malformed hooks/notifications")

contrib/pyln-testing/pyln/testing/utils.py

@@ -841,7 +841,7 @@ def call(self, method, payload=None, cmdprefix=None, filter=None):
 
 
 class LightningNode(object):
-    def __init__(self, node_id, lightning_dir, bitcoind, executor, valgrind, may_fail=False,
+    def __init__(self, node_id, lightning_dir, bitcoind, executor, may_fail=False,
                  may_reconnect=False,
                  broken_log=None,
                  allow_warning=False,
@@ -900,7 +900,7 @@ def __init__(self, node_id, lightning_dir, bitcoind, executor, valgrind, may_fai
             self.daemon.opts["dev-debugger"] = dbgvar
         if os.getenv("DEBUG_LIGHTNINGD"):
             self.daemon.opts["dev-debug-self"] = None
-        if valgrind:
+        if VALGRIND:
             self.daemon.env["LIGHTNINGD_DEV_NO_BACKTRACE"] = "1"
             self.daemon.opts["dev-no-plugin-checksum"] = None
         else:
@@ -926,7 +926,7 @@ def __init__(self, node_id, lightning_dir, bitcoind, executor, valgrind, may_fai
         dsn = db.get_dsn()
         if dsn is not None:
             self.daemon.opts['wallet'] = dsn
-        if valgrind:
+        if VALGRIND:
             trace_skip_pattern = '*python*,*bitcoin-cli*,*elements-cli*,*cln-grpc*,*clnrest*,*wss-proxy*,*cln-bip353*,*reckless'
             if not valgrind_plugins:
                 trace_skip_pattern += ',*plugins*'
@@ -1653,10 +1653,6 @@ class NodeFactory(object):
     """
     def __init__(self, request, testname, bitcoind, executor, directory,
                  db_provider, node_cls, jsonschemas):
-        if request.node.get_closest_marker("slow_test") and SLOW_MACHINE:
-            self.valgrind = False
-        else:
-            self.valgrind = VALGRIND
         self.testname = testname
 
         # Set test name in environment for coverage file organization
@@ -1755,7 +1751,7 @@ def get_node(self, node_id=None, options=None, dbfile=None,
         db = self.db_provider.get_db(os.path.join(lightning_dir, TEST_NETWORK), self.testname, node_id)
         db.provider = self.db_provider
         node = self.node_cls(
-            node_id, lightning_dir, self.bitcoind, self.executor, self.valgrind, db=db,
+            node_id, lightning_dir, self.bitcoind, self.executor, db=db,
             port=port, grpc_port=grpc_port, options=options, may_fail=may_fail or expect_fail,
             jsonschemas=self.jsonschemas,
             **kwargs
@@ -1872,7 +1868,7 @@ def killall(self, expected_successes):
             # leak detection upsets VALGRIND by reading uninitialized mem,
             # and valgrind adds extra fds.
             # If it's dead, we'll catch it below.
-            if not self.valgrind:
+            if not VALGRIND:
                 try:
                     # This also puts leaks in log.
                     leaks = self.nodes[i].rpc.dev_memleak()['leaks']

gossipd/gossmap_manage.c

@@ -1332,7 +1332,6 @@ void gossmap_manage_channel_spent(struct gossmap_manage *gm,
 				  struct short_channel_id scid)
 {
 	struct gossmap_chan *chan;
-	const struct gossmap_node *me;
 	const u8 *msg;
 	struct chan_dying cd;
 	struct gossmap *gossmap = gossmap_manage_get_gossmap(gm);
@@ -1341,14 +1340,6 @@ void gossmap_manage_channel_spent(struct gossmap_manage *gm,
 	if (!chan)
 		return;
 
-	me = gossmap_find_node(gossmap, &gm->daemon->id);
-	/* We delete our own channels immediately, since we have local knowledge */
-	if (gossmap_nth_node(gossmap, chan, 0) == me
-	    || gossmap_nth_node(gossmap, chan, 1) == me) {
-		kill_spent_channel(gm, gossmap, scid);
-		return;
-	}
-
 	/* Is it already dying?  It's lightningd re-telling us */
 	if (channel_already_dying(gm->dying_channels, scid))
 		return;

hsmd/libhsmd.c

@@ -1821,6 +1821,17 @@ static u8 *handle_sign_anchorspend(struct hsmd_client *c, const u8 *msg_in)
 				    fmt_wally_psbt(tmpctx, psbt));
 	}
 
+	if (dev_warn_on_overgrind) {
+		for (size_t i = 0; i < psbt->num_inputs; i++) {
+			if (psbt->inputs[i].signatures.num_items == 1
+			    && psbt->inputs[i].signatures.items[0].value_len < 71) {
+				hsmd_status_fmt(LOG_BROKEN, NULL,
+						"overgrind: short signature length %zu",
+						psbt->inputs[i].signatures.items[0].value_len);
+			}
+		}
+	}
+
 	return towire_hsmd_sign_anchorspend_reply(NULL, psbt);
 }
 

lightningd/channel_gossip.c

@@ -1096,13 +1096,15 @@ void channel_gossip_update_from_gossipd(struct channel *channel,
 	case CGOSSIP_WAITING_FOR_USABLE:
 	case CGOSSIP_CHANNEL_DEAD:
 	case CGOSSIP_CHANNEL_UNANNOUNCED_DYING:
-	case CGOSSIP_CHANNEL_ANNOUNCED_DEAD:
 		/* Shouldn't happen. */
 		log_broken(channel->log,
 			   "gossipd gave channel_update in %s? update=%s",
 			   channel_gossip_state_str(channel->channel_gossip->state),
 			   tal_hex(tmpctx, channel_update));
 	/* fall thru */
+	/* ANNOUNCED_DEAD can happen is gossipd hadn't processed block
+	 * when we restarted; ignore, as it will catch up soon. */
+	case CGOSSIP_CHANNEL_ANNOUNCED_DEAD:
 	case CGOSSIP_CHANNEL_ANNOUNCED_DYING:
 		if (taken(channel_update))
 			tal_free(channel_update);

lightningd/connect_control.c

@@ -277,10 +277,22 @@ static void connect_failed(struct lightningd *ld,
 					  connect_nsec,
 					  connect_attempted);
 
-	/* We can have multiple connect commands: fail them all */
-	while ((c = find_connect(ld, id)) != NULL) {
-		/* They delete themselves from list */
-		was_pending(command_fail(c->cmd, errcode, "%s", errmsg));
+	/* There's a race between autoreconnect and connect commands.  This
+	 * matters because the autoreconnect might have failed, but that was before
+	 * the connect_to_peer command gave connectd a new address.  This we wait for
+	 * one we explicitly asked for before failing.
+	 *
+	 * A similar pattern could occur with multiple connect commands, however connectd
+	 * does simply combine those, so we don't get a response per request, and it's a
+	 * very rare corner case (which, unlike the above, doesn't happen in CI!).
+	 */
+	if (strstarts(connect_reason, "connect command")
+	    || errcode == CONNECT_DISCONNECTED_DURING) {
+		/* We can have multiple connect commands: fail them all */
+		while ((c = find_connect(ld, id)) != NULL) {
+			/* They delete themselves from list */
+			was_pending(command_fail(c->cmd, errcode, "%s", errmsg));
+		}
 	}
 }
 

lightningd/pay.c

@@ -745,8 +745,13 @@ static struct command_result *wait_payment(struct lightningd *ld,
 			/* FIXME: We don't store this! */
 			fail->msg = NULL;
 
-			rpcerrorcode = faildestperm ? PAY_DESTINATION_PERM_FAIL
-						    : PAY_TRY_OTHER_ROUTE;
+			/* Peers which fail directly can hit this! */
+			if (failcode & BADONION)
+				rpcerrorcode = PAY_UNPARSEABLE_ONION;
+			else if (faildestperm)
+				rpcerrorcode = PAY_DESTINATION_PERM_FAIL;
+			else
+				rpcerrorcode = PAY_TRY_OTHER_ROUTE;
 
 			return sendpay_fail(
 			    cmd, payment, rpcerrorcode, NULL, fail,

lightningd/subd.c

@@ -438,6 +438,8 @@ static bool handle_peer_error(struct subd *sd, const u8 *msg, int fds[1])
 
 	/* Don't free sd; we may be about to free channel. */
 	sd->channel = NULL;
+	/* While it's cleaning up, this is not a leak! */
+	notleak(sd);
 	sd->errcb(channel, peer_fd, desc, err_for_them, disconnect, warning);
 	return true;
 }
@@ -641,6 +643,8 @@ static void destroy_subd(struct subd *sd)
 
 		/* Clear any transient messages in billboard */
 		sd->billboardcb(channel, false, NULL);
+		/* While it's cleaning up, this is not a leak! */
+		notleak(sd);
 		sd->channel = NULL;
 
 		/* We can be freed both inside msg handling, or spontaneously. */
@@ -928,11 +932,6 @@ void subd_release_channel(struct subd *owner, const void *channel)
 		assert(owner->channel == channel);
 		owner->channel = NULL;
 		tal_free(owner);
-	} else {
-		/* Caller has reassigned channel->owner, so there's no pointer
-		 * to this subd owner while it's freeing itself.  If we
-		 * ask memleak right now, it will complain! */
-		notleak(owner);
 	}
 }
 

plugins/askrene/askrene.c

@@ -573,6 +573,7 @@ static struct command_result *do_getroutes(struct command *cmd,
 	struct route **routes;
 	struct flow **flows;
 	struct json_stream *response;
+	const struct gossmap_node *me;
 
 	/* update the gossmap */
 	if (gossmap_refresh(askrene->gossmap)) {
@@ -593,6 +594,30 @@ static struct command_result *do_getroutes(struct command *cmd,
 	rq->additional_costs = info->additional_costs;
 	rq->maxparts = info->maxparts;
 
+	/* We also eliminate any local channels we *know* are dying.
+	 * Most channels get 12 blocks grace in case it's a splice,
+	 * but if it's us, we know about the splice already. */
+	me = gossmap_find_node(rq->gossmap, &askrene->my_id);
+	if (me) {
+		for (size_t i = 0; i < me->num_chans; i++) {
+			struct short_channel_id_dir scidd;
+			const struct gossmap_chan *c = gossmap_nth_chan(rq->gossmap,
+									me, i, NULL);
+			if (!gossmap_chan_is_dying(rq->gossmap, c))
+				continue;
+
+			scidd.scid = gossmap_chan_scid(rq->gossmap, c);
+			/* Disable both directions */
+			for (scidd.dir = 0; scidd.dir < 2; scidd.dir++) {
+				bool enabled = false;
+				gossmap_local_updatechan(localmods,
+							 &scidd,
+							 &enabled,
+							 NULL, NULL, NULL, NULL, NULL);
+			}
+		}
+	}
+
 	/* apply selected layers to the localmods */
 	apply_layers(askrene, rq, &info->source, info->amount, localmods,
 		     info->layers, info->local_layer);

plugins/channel_hint.c

@@ -30,8 +30,14 @@ void channel_hint_to_json(const char *name, const struct channel_hint *hint,
 	json_object_start(dest, name);
 	json_add_u32(dest, "timestamp", hint->timestamp);
 	json_add_short_channel_id_dir(dest, "scid", hint->scid);
-	json_add_amount_msat(dest, "estimated_capacity_msat",
-			     hint->estimated_capacity);
+	/* The estimated_capacity is unset if it's not enabled; use total_capacity */
+	if (hint->enabled) {
+		json_add_amount_msat(dest, "estimated_capacity_msat",
+				     hint->estimated_capacity);
+	} else {
+		json_add_amount_msat(dest, "estimated_capacity_msat",
+				     hint->capacity);
+	}
 	json_add_amount_msat(dest, "total_capacity_msat", hint->capacity);
 	json_add_bool(dest, "enabled", hint->enabled);
 	json_object_end(dest);

tests/benchmark.py

@@ -1,7 +1,8 @@
 from concurrent import futures
 from fixtures import *  # noqa: F401,F403
+from pyln.client import RpcError
 from tqdm import tqdm
-from utils import (wait_for, TIMEOUT)
+from utils import (wait_for, TIMEOUT, only_one)
 
 
 import os
@@ -228,3 +229,36 @@ def test_spam_listcommands(node_factory, bitcoind, benchmark):
 
     # This calls "listinvoice" 100,000 times (which doesn't need a transaction commit)
     benchmark(l1.rpc.spamlistcommand, 100_000)
+
+
+def test_payment_speed(node_factory, benchmark):
+    """This makes sure we don't screw up nagle handling.
+
+    Normally:
+    Name (time in ms)           Min       Max      Mean  StdDev    Median     IQR  Outliers     OPS  Rounds  Iterations
+    test_payment_speed      16.3587  40.4925  27.4874  5.5512  27.7885  8.9291       9;0  36.3803      33           1
+
+    Without TCP_NODELAY:
+    Name (time in ms)           Min       Max      Mean  StdDev    Median     IQR  Outliers     OPS  Rounds  Iterations
+    test_payment_speed     153.7132  163.2027  158.6747  3.4059  158.5219  6.3745       3;0  6.3022       9           1
+    """
+    l1 = get_bench_node(node_factory, extra_options={'commit-time': 0})
+    l2 = get_bench_node(node_factory, extra_options={'commit-time': 0})
+
+    node_factory.join_nodes([l1, l2])
+
+    scid = only_one(l1.rpc.listpeerchannels()['channels'])['short_channel_id']
+    routestep = {
+        'amount_msat': 100,
+        'id': l2.info['id'],
+        'delay': 5,
+        'channel': scid
+    }
+
+    def onepay(l1, routestep):
+        phash = random.randbytes(32).hex()
+        l1.rpc.sendpay([routestep], phash)
+        with pytest.raises(RpcError, match="WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS"):
+            l1.rpc.waitsendpay(phash)
+
+    benchmark(onepay, l1, routestep)

tests/conftest.py

@@ -1,6 +1,6 @@
 import pytest
 
-from pyln.testing.utils import EXPERIMENTAL_DUAL_FUND
+from pyln.testing.utils import EXPERIMENTAL_DUAL_FUND, VALGRIND, SLOW_MACHINE
 
 
 # This function is based upon the example of how to
@@ -37,3 +37,5 @@ def pytest_runtest_setup(item):
     else:  # If there's no openchannel marker, skip if EXP_DF
         if EXPERIMENTAL_DUAL_FUND:
             pytest.skip('v1-only test, EXPERIMENTAL_DUAL_FUND=1')
+    if "slow_test" in item.keywords and VALGRIND and SLOW_MACHINE:
+        pytest.skip("Skipping slow tests under VALGRIND")