Merge pull request #10288 from f321x/debug_failing_regtest

ci/regtest: fix flaky regtest test lnwatcher_waits_until_fees_go_down

Author: SomberNight

.cirrus.yml

@@ -183,9 +183,16 @@ task:
     - tests/regtest/run_bitcoind.sh
   electrumx_service_background_script:
     - tests/regtest/run_electrumx.sh
+  # if any test fails, the test will get aborted (--failfast) and the wallet directories will be
+  # available for download in the Cirrus UI
   regtest_script:
     - sleep 10s
-    - python3 -m unittest tests/regtest.py
+    - python3 -m unittest tests/regtest.py --failfast || TEST_EXIT_CODE=$?
+    - tar -czf test_wallets.tar.gz /tmp/alice /tmp/bob /tmp/carol || true
+    - exit ${TEST_EXIT_CODE:-0}
+  on_failure:
+    wallet_artifacts:
+      path: "test_wallets.tar.gz"
   env:
     LD_LIBRARY_PATH: contrib/_saved_secp256k1_build/
     ELECTRUM_REQUIREMENTS: contrib/requirements/requirements.txt

electrum/commands.py

@@ -1624,6 +1624,8 @@ async def getfeerate(self):
     async def test_inject_fee_etas(self, fee_est):
         """
         Inject fee estimates into the network object, as if they were coming from connected servers.
+        `setconfig 'test_disable_automatic_fee_eta_update' true` to prevent Network from overriding
+        the configured fees.
         Useful on regtest.
 
         arg:str:fee_est:dict of ETA-based fee estimates, encoded as str

electrum/lnwatcher.py

@@ -210,10 +210,12 @@ def maybe_redeem(self, sweep_info: 'SweepInfo') -> bool:
         try:
             self.lnworker.wallet.txbatcher.add_sweep_input('lnwatcher', sweep_info)
         except BelowDustLimit:
+            self.logger.debug(f"maybe_redeem: BelowDustLimit: {sweep_info.name}")
             # utxo is considered dust at *current* fee estimates.
             # but maybe the fees atm are very high? We will retry later.
             pass
         except NoDynamicFeeEstimates:
+            self.logger.debug(f"maybe_redeem: NoDynamicFeeEstimates: {sweep_info.name}")
             pass  # will retry later
         if sweep_info.is_anchor():
             return False

electrum/network.py

@@ -612,6 +612,8 @@ def get_fee_estimates(self):
 
     def update_fee_estimates(self, *, fee_est: Dict[int, int] = None):
         if fee_est is None:
+            if self.config.TEST_DISABLE_AUTOMATIC_FEE_ETA_UPDATE:
+                return
             fee_est = self.get_fee_estimates()
         for nblock_target, fee in fee_est.items():
             self.fee_estimates.set_data(nblock_target, fee)

electrum/simple_config.py

@@ -775,6 +775,7 @@ def __setattr__(self, name, value):
     FEE_POLICY = ConfigVar('fee_policy.default', default='eta:2', type_=str)  # exposed to GUI
     FEE_POLICY_LIGHTNING = ConfigVar('fee_policy.lnwatcher', default='eta:2', type_=str)  # for txbatcher (sweeping)
     FEE_POLICY_SWAPS = ConfigVar('fee_policy.swaps', default='eta:2', type_=str)  # for txbatcher (sweeping and sending if we are a swapserver)
+    TEST_DISABLE_AUTOMATIC_FEE_ETA_UPDATE = ConfigVar('test_disable_automatic_fee_eta_update', default=False, type_=bool)
 
     RPC_USERNAME = ConfigVar('rpcuser', default=None, type_=str)
     RPC_PASSWORD = ConfigVar('rpcpassword', default=None, type_=str)

electrum/txbatcher.py

@@ -272,9 +272,10 @@ def is_dust(self, sweep_info: SweepInfo) -> bool:
         value = sweep_info.txin.value_sats()
         witness_size = len(sweep_info.txin.make_witness(71*b'\x00'))
         tx_size_vbytes = 84 + witness_size//4     # assumes no batching, sweep to p2wpkh
-        self.logger.info(f'{sweep_info.name} size = {tx_size_vbytes}')
         fee = self.fee_policy.estimate_fee(tx_size_vbytes, network=self.wallet.network)
-        return value - fee <= dust_threshold()
+        is_dust = value - fee <= dust_threshold()
+        self.logger.info(f'{sweep_info.name} size = {tx_size_vbytes}: {is_dust=}')
+        return is_dust
 
     @locked
     def add_sweep_input(self, sweep_info: 'SweepInfo') -> None:

tests/regtest/regtest.sh

@@ -22,8 +22,17 @@ function wait_until_htlcs_settled()
 {
     msg="wait until $1's local_unsettled_sent is zero"
     cmd="./run_electrum --regtest -D /tmp/$1"
+    declare -i timeout_sec=30
+    declare -i elapsed_sec=0
+
     while unsettled=$($cmd list_channels | jq '.[] | .local_unsettled_sent') && [ $unsettled != "0" ]; do
+        if ((elapsed_sec > timeout_sec)); then
+            printf "Timeout of %i s exceeded\n" "$elapsed_sec"
+            exit 1
+        fi
+
         sleep 1
+        elapsed_sec=$((elapsed_sec + 1))
         msg="$msg."
         printf "$msg\r"
     done
@@ -35,8 +44,17 @@ function wait_for_balance()
 {
     msg="wait until $1's balance reaches $2"
     cmd="./run_electrum --regtest -D /tmp/$1"
+    declare -i timeout_sec=30
+    declare -i elapsed_sec=0
+
     while balance=$($cmd getbalance | jq '[.confirmed, .unconfirmed] | to_entries | map(select(.value != null).value) | map(tonumber) | add ') && (( $(echo "$balance < $2" | bc -l) )); do
+        if ((elapsed_sec > timeout_sec)); then
+            printf "Timeout of %i s exceeded\n" "$elapsed_sec"
+            exit 1
+        fi
+
         sleep 1
+        elapsed_sec=$((elapsed_sec + 1))
         msg="$msg."
         printf "$msg\r"
     done
@@ -47,8 +65,17 @@ function wait_until_channel_open()
 {
     msg="wait until $1 sees channel open"
     cmd="./run_electrum --regtest -D /tmp/$1"
+    declare -i timeout_sec=30
+    declare -i elapsed_sec=0
+
     while channel_state=$($cmd list_channels | jq '.[0] | .state' | tr -d '"') && [ $channel_state != "OPEN" ]; do
+        if ((elapsed_sec > timeout_sec)); then
+            printf "Timeout of %i s exceeded\n" "$elapsed_sec"
+            exit 1
+        fi
+
         sleep 1
+        elapsed_sec=$((elapsed_sec + 1))
         msg="$msg."
         printf "$msg\r"
     done
@@ -59,8 +86,17 @@ function wait_until_channel_closed()
 {
     msg="wait until $1 sees channel closed"
     cmd="./run_electrum --regtest -D /tmp/$1"
+    declare -i timeout_sec=30
+    declare -i elapsed_sec=0
+
     while [[ $($cmd list_channels | jq '.[0].state' | tr -d '"') != "CLOSED" ]]; do
+        if ((elapsed_sec > timeout_sec)); then
+            printf "Timeout of %i s exceeded\n" "$elapsed_sec"
+            exit 1
+        fi
+
         sleep 1
+        elapsed_sec=$((elapsed_sec + 1))
         msg="$msg."
         printf "$msg\r"
     done
@@ -71,8 +107,17 @@ function wait_until_preimage()
 {
     msg="wait until $1 has preimage for $2"
     cmd="./run_electrum --regtest -D /tmp/$1"
+    declare -i timeout_sec=30
+    declare -i elapsed_sec=0
+
     while [[ $($cmd get_invoice $2 | jq '.preimage' | tr -d '"') == "null" ]]; do
+        if ((elapsed_sec > timeout_sec)); then
+            printf "Timeout of %i s exceeded\n" "$elapsed_sec"
+            exit 1
+        fi
+
         sleep 1
+        elapsed_sec=$((elapsed_sec + 1))
         msg="$msg."
         printf "$msg\r"
     done
@@ -82,8 +127,17 @@ function wait_until_preimage()
 function wait_until_spent()
 {
     msg="wait until $1:$2 is spent"
+    declare -i timeout_sec=30
+    declare -i elapsed_sec=0
+
     while [[ $($bitcoin_cli gettxout $1 $2) ]]; do
+        if ((elapsed_sec > timeout_sec)); then
+            printf "Timeout of %i s exceeded\n" "$elapsed_sec"
+            exit 1
+        fi
+
         sleep 1
+        elapsed_sec=$((elapsed_sec + 1))
         msg="$msg."
         printf "$msg\r"
     done
@@ -331,6 +385,7 @@ if [[ $1 == "lnwatcher_waits_until_fees_go_down" ]]; then
     $alice setconfig test_force_disable_mpp true
     $alice setconfig test_force_mpp false
     wait_for_balance alice 1
+    $alice setconfig test_disable_automatic_fee_eta_update true
     $alice test_inject_fee_etas "{2:1000}"
     $bob test_inject_fee_etas "{2:1000}"
     echo "alice opens channel"