Merge #598: Unflake functional test that we retry requests to bitcoind on getting a 503.

0f6fc48e88344a8d0f7f5be68503482ba92105cf qa: only run the RPC retry functional test with bitcoind 25.0 (Antoine Poinsot)
be2030af283f214e90230271f0df11990c25b512 qa: unflake the test_retry_on_workqueue_exceeded functional test (Antoine Poinsot)
b96db71a4de557c762fe583de8635b94f3bff210 qa: bitcoind: add a helper for sending a P2P message to bitcoind (Antoine Poinsot)
df396cccc8d009c53a47e0b9bcca2603f42bbeba qa: set load_on_startup for bitcoind internal wallet (Antoine Poinsot)

Pull request description:

  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.

  Fixes #573.

ACKs for top commit:
  darosior:
    self-ACK 0f6fc48e88344a8d0f7f5be68503482ba92105cf -- extensively tested it locally.

Tree-SHA512: bd12fb525a46ccf543fb8774370f5b5064723f578de51723b15a420cbc576cb5ef579e7d6ffe38a287ee7c7742887e61a01b76be4fb0858313d4712f1b00f1c0
This commit is contained in:
Antoine Poinsot 2023-08-09 18:13:50 +02:00
commit 5b6c2b5c43
No known key found for this signature in database
GPG Key ID: E13FC145CD3F4304
5 changed files with 154 additions and 18 deletions

View File

@ -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

View File

@ -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:

View File

@ -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()

View File

@ -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

View File

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