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/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: 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() 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 189b85ca..6156a865 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -1,8 +1,19 @@ +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, + IS_BITCOIND_25, +) from threading import Thread @@ -255,7 +266,28 @@ 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): +@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) + 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 + + +@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 # as we don't support yet restarting a bitcoind due to the cookie file getting @@ -264,19 +296,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)