From df396cccc8d009c53a47e0b9bcca2603f42bbeba Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Aug 2023 12:13:30 +0200 Subject: [PATCH 1/4] qa: set load_on_startup for bitcoind internal wallet --- tests/fixtures.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/fixtures.py b/tests/fixtures.py index f36d24cb..1c4c8624 100644 --- a/tests/fixtures.py +++ b/tests/fixtures.py @@ -102,7 +102,9 @@ def bitcoind(directory): bitcoind = Bitcoind(bitcoin_dir=os.path.join(directory, "bitcoind")) bitcoind.startup() - bitcoind.rpc.createwallet(bitcoind.rpc.wallet_name, False, False, "", False, True) + bitcoind.rpc.createwallet( + bitcoind.rpc.wallet_name, False, False, "", False, True, True + ) bitcoind.rpc.generatetoaddress(101, bitcoind.rpc.getnewaddress()) while bitcoind.rpc.getbalance() < 50: From b96db71a4de557c762fe583de8635b94f3bff210 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Aug 2023 12:14:18 +0200 Subject: [PATCH 2/4] qa: bitcoind: add a helper for sending a P2P message to bitcoind --- tests/test_framework/bitcoind.py | 77 +++++++++++++++++++++++++++++++- 1 file changed, 76 insertions(+), 1 deletion(-) diff --git a/tests/test_framework/bitcoind.py b/tests/test_framework/bitcoind.py index 5555d6b4..ab8e69ac 100644 --- a/tests/test_framework/bitcoind.py +++ b/tests/test_framework/bitcoind.py @@ -1,5 +1,8 @@ +import hashlib import logging import os +import socket +import time from decimal import Decimal from ephemeral_port_reserve import reserve @@ -53,11 +56,13 @@ class Bitcoind(TailableProc): "-datadir={}".format(bitcoin_dir), "-printtoconsole", "-server", + "-debug=1", + "-debugexclude=libevent", + "-debugexclude=tor", ] bitcoind_conf = { "port": self.p2pport, "rpcport": rpcport, - "debug": 1, "fallbackfee": Decimal(1000) / COIN, "rpcthreads": 32, } @@ -179,6 +184,76 @@ class Bitcoind(TailableProc): self.generate_block(1 + final_len - (height + shift), memp) self.wait_for_log(r"UpdateTip: new best=.* height={}".format(final_len)) + def send_p2p_message(self, s, command, payload): + magic_bytes = b"\xfa\xbf\xb5\xda" + checksum = hashlib.sha256(hashlib.sha256(payload).digest()).digest()[:4] + payload_len = len(payload).to_bytes(4, "little") + message = ( + magic_bytes + + command.encode("ascii") + + bytes(12 - len(command)) + + payload_len + + checksum + + payload + ) + s.sendall(message) + logging.debug(f"Sent message to bitcoind: {command}") + + def connect_p2p(self, cur_height): + version = int(70016).to_bytes(4, "little") + services = int((1 << 0) | (1 << 3)).to_bytes(8, "little") + timestamp = int(time.time()).to_bytes(8, "little") + addr_recv = services + bytes(16) + self.p2pport.to_bytes(2, "little") + addr_from = addr_recv + nonce = os.urandom(8) + user_agent = b"\x00" + start_height = cur_height.to_bytes(4, "little") + relay = b"\x00" + ver_payload = ( + version + + services + + timestamp + + addr_recv + + addr_from + + nonce + + user_agent + + start_height + + relay + ) + + logging.debug("Connecting to bitcoind p2p port") + s = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + s.connect(("127.0.0.1", self.p2pport)) + self.send_p2p_message(s, "version", ver_payload) + s.recv(102 + 24) # Recv version + s.recv(0 + 24) # Recv wtxidrelay + s.recv(0 + 24) # Recv sendaddrv2 + s.recv(0 + 24) # Recv verack + self.send_p2p_message(s, "verack", b"") + s.recv(9 + 24) # Recv sendcmpct + ping = s.recv(8 + 24) # Recv ping, reply with pong + assert ping[4:8].decode("ascii") == "ping", ping + self.send_p2p_message(s, "pong", ping[-8:]) + s.recv(613 + 24) # Recv getheaders (ignore it) + s.recv(8 + 24) # Recv feefilter + + logging.debug("Handshake to bitcoind complete") + return s + + def submit_block(self, cur_height, block_hex): + """Submit a block through the P2P interface.""" + s = self.connect_p2p(cur_height) + self.send_p2p_message(s, "block", bytes.fromhex(block_hex)) + + # Make sure the block was received by waiting for the inv. + inv = s.recv(37 + 24) + assert ( + inv[4:7].decode("ascii") == "inv" + and int.from_bytes(inv[24 + 1 : 24 + 1 + 4], "little") == 2 + ), inv + + s.close() + def startup(self): try: self.start() From be2030af283f214e90230271f0df11990c25b512 Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Aug 2023 12:15:22 +0200 Subject: [PATCH 3/4] qa: unflake the test_retry_on_workqueue_exceeded functional test This was racy as it was relying on the `waitfornewblock` timeout, so it would occasionally fail in CI. Make this test more robust by having `waitfornewblock` wait indefinitely and submitting a block through the P2P interface to unstuck it. --- tests/test_misc.py | 85 +++++++++++++++++++++++++++++++++++++--------- 1 file changed, 69 insertions(+), 16 deletions(-) diff --git a/tests/test_misc.py b/tests/test_misc.py index 189b85ca..f1760a39 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -1,8 +1,18 @@ +import logging import pytest +import time from fixtures import * +from test_framework.authproxy import JSONRPCException from test_framework.serializations import PSBT -from test_framework.utils import wait_for, RpcError, OLD_LIANAD_PATH, LIANAD_PATH, COIN +from test_framework.utils import ( + wait_for, + RpcError, + OLD_LIANAD_PATH, + LIANAD_PATH, + COIN, + TIMEOUT, +) from threading import Thread @@ -255,7 +265,25 @@ def test_migration(lianad_multisig, bitcoind): assert len(spend_txs) == 2 and all(s["updated_at"] is not None for s in spend_txs) -def test_retry_on_workqueue_exceeded(lianad, bitcoind): +def test_bitcoind_submit_block(bitcoind): + block_count = bitcoind.rpc.getblockcount() + block = bitcoind.rpc.generateblock(bitcoind.rpc.getnewaddress(), [], False) + bitcoind.submit_block(block_count, block["hex"]) + wait_for(lambda: bitcoind.rpc.getblockcount() == block_count + 1) + + +def bitcoind_wait_new_block(bitcoind): + """Call 'waitfornewblock', retry on 503.""" + while True: + try: + bitcoind.rpc.waitfornewblock() + return + except JSONRPCException as e: + logging.debug(f"Error calling waitfornewblock: {str(e)}") + time.sleep(0.1) + continue + +def test_retry_on_workqueue_exceeded(lianad, bitcoind, executor): """Make sure we retry requests to bitcoind if it is temporarily overloaded.""" # Start by reducing the work queue to a single slot. Note we need to stop lianad # as we don't support yet restarting a bitcoind due to the cookie file getting @@ -264,19 +292,44 @@ def test_retry_on_workqueue_exceeded(lianad, bitcoind): bitcoind.cmd_line += ["-rpcworkqueue=1", "-rpcthreads=1"] bitcoind.stop() bitcoind.start() + + # Mine a block but don't submit it yet, we'll use it to unstuck `waitfornewblock`. + block_count = bitcoind.rpc.getblockcount() + block = bitcoind.rpc.generateblock(bitcoind.rpc.getnewaddress(), [], False) + + # Only restart Liana now to make sure the above bitcoind RPCs don't conflict with the + # ones performed by Liana at startup. lianad.start() - # Stuck the bitcoind RPC server working queue with a command that takes 5 seconds - # to be replied to, and make lianad send it a request. Make sure we detect this is - # a transient HTTP 503 error and we retry the request. Once the 5 seconds are past - # our request succeeds and we get the reply to the lianad RPC command. - t = Thread(target=bitcoind.rpc.waitfornewblock, args=(5_000,)) - t.start() - lianad.rpc.getinfo() - lianad.wait_for_logs( - [ - "Transient error when sending request to bitcoind.*(status: 503, body: Work queue depth exceeded)", - "Retrying RPC request to bitcoind", - ] - ) - t.join() + # Clog the bitcoind RPC server working queue until we get a new block. This is to + # make our upcoming call to bitcoind RPC through lianad fail with a 503 error. + f_wait = executor.submit(bitcoind_wait_new_block, bitcoind) + + # Now send an RPC command to lianad that will involve it making one to bitcoind. This + # command to bitcoind should fail and we should retry it. + # We use a loop to make sure lianad hits a 503 when connecting to bitcoind, and not a + # (very long) timeout while awaiting the response. + while True: + f_liana = executor.submit(lianad.rpc.getinfo) + try: + lianad.wait_for_logs( + [ + "Transient error when sending request to bitcoind.*(status: 503, body: Work queue depth exceeded)", + "Retrying RPC request to bitcoind", + ], + timeout=5 + ) + except TimeoutError: + continue + finally: + logging.info("Didn't raise. Trying again.") + break + + # Submit the mined block to bitcoind through its P2P interface, it would make `waitfornewblock` + # return, thereby unclogging the RPC work queue and unstucking the `getinfo` call to Liana. + bitcoind.submit_block(block_count, block["hex"]) + f_wait.result(TIMEOUT) + + # We should have retried the request to bitcoind, which should now succeed along with the call. + # This just checks the response we get is sane, nothing particular with this field. + assert "block_height" in f_liana.result(TIMEOUT) From 0f6fc48e88344a8d0f7f5be68503482ba92105cf Mon Sep 17 00:00:00 2001 From: Antoine Poinsot Date: Wed, 9 Aug 2023 13:07:17 +0200 Subject: [PATCH 4/4] qa: only run the RPC retry functional test with bitcoind 25.0 --- .cirrus.yml | 1 + tests/test_framework/utils.py | 1 + tests/test_misc.py | 6 +++++- 3 files changed, 7 insertions(+), 1 deletion(-) diff --git a/.cirrus.yml b/.cirrus.yml index a0424d01..64156c53 100644 --- a/.cirrus.yml +++ b/.cirrus.yml @@ -51,6 +51,7 @@ task: echo "49df6e444515d457ea0b885d66f521f2a26ca92ccf73d5296082e633544253bf bitcoin-24.0.1-x86_64-linux-gnu.tar.gz" | sha256sum -c tar -xzf bitcoin-24.0.1-x86_64-linux-gnu.tar.gz export BITCOIND_PATH=bitcoin-24.0.1/bin/bitcoind + export IS_BITCOIND_25=0 else # Download the bitcoind binary curl -O https://bitcoincore.org/bin/bitcoin-core-25.0/bitcoin-25.0-x86_64-linux-gnu.tar.gz diff --git a/tests/test_framework/utils.py b/tests/test_framework/utils.py index 15303250..c599e211 100644 --- a/tests/test_framework/utils.py +++ b/tests/test_framework/utils.py @@ -23,6 +23,7 @@ LIANAD_PATH = os.getenv("LIANAD_PATH", DEFAULT_MS_PATH) DEFAULT_BITCOIND_PATH = "bitcoind" BITCOIND_PATH = os.getenv("BITCOIND_PATH", DEFAULT_BITCOIND_PATH) OLD_LIANAD_PATH = os.getenv("OLD_LIANAD_PATH", None) +IS_BITCOIND_25 = bool(int(os.getenv("IS_BITCOIND_25", True))) COIN = 10 ** 8 diff --git a/tests/test_misc.py b/tests/test_misc.py index f1760a39..6156a865 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -12,6 +12,7 @@ from test_framework.utils import ( LIANAD_PATH, COIN, TIMEOUT, + IS_BITCOIND_25, ) from threading import Thread @@ -265,6 +266,7 @@ def test_migration(lianad_multisig, bitcoind): assert len(spend_txs) == 2 and all(s["updated_at"] is not None for s in spend_txs) +@pytest.mark.skipif(not IS_BITCOIND_25, reason="Need 'generateblock' with 'submit=False'") def test_bitcoind_submit_block(bitcoind): block_count = bitcoind.rpc.getblockcount() block = bitcoind.rpc.generateblock(bitcoind.rpc.getnewaddress(), [], False) @@ -283,6 +285,8 @@ def bitcoind_wait_new_block(bitcoind): time.sleep(0.1) continue + +@pytest.mark.skipif(not IS_BITCOIND_25, reason="Need 'generateblock' with 'submit=False'") def test_retry_on_workqueue_exceeded(lianad, bitcoind, executor): """Make sure we retry requests to bitcoind if it is temporarily overloaded.""" # Start by reducing the work queue to a single slot. Note we need to stop lianad @@ -317,7 +321,7 @@ def test_retry_on_workqueue_exceeded(lianad, bitcoind, executor): "Transient error when sending request to bitcoind.*(status: 503, body: Work queue depth exceeded)", "Retrying RPC request to bitcoind", ], - timeout=5 + timeout=5, ) except TimeoutError: continue