Skip to content

test: Add diagnostic logging to investigate intermittent electrs failures in CI #849

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
joostjager wants to merge 13 commits into
base: main
Choose a base branch
from
Draft

test: Add diagnostic logging to investigate intermittent electrs failures in CI #849

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
13 commits
Select commit Hold shift + click to select a range
33927c3
test: Add diagnostic logging for electrs process failures
joostjager Mar 26, 2026
163569b
ci: Add stress-test job to reproduce intermittent electrs failures
joostjager Mar 26, 2026
6de9312
ci: Run 3 concurrent test processes across 3 stress-test shards
joostjager Mar 26, 2026
baaa6ff
test: Support configurable base port for concurrent test processes
joostjager Mar 26, 2026
fc11c64
ci: Use unique base ports per iteration to avoid TIME_WAIT collisions
joostjager Mar 26, 2026
1bd1672
ci: Dump dmesg OOM/kill messages on test failure
joostjager Mar 27, 2026
4736ce2
test: Use random ports with retry loop instead of deterministic alloc…
joostjager Mar 27, 2026
0c83072
test: Use fresh storage directory on port collision retry
joostjager Mar 27, 2026
d9a1f97
test: Log which process holds a port on InvalidSocketAddress
joostjager Mar 27, 2026
cdc77a2
test: Fix announcement address assertion and simplify stress test
joostjager Mar 27, 2026
72f1764
test: Use atomic counter with random base for port allocation
joostjager Mar 27, 2026
6153551
test: Fix port 0 bug in atomic counter initialization
joostjager Mar 27, 2026
f4726a2
test: Use port range below Linux ephemeral range to avoid collisions
joostjager Mar 27, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
58 changes: 58 additions & 0 deletions .github/workflows/rust.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -81,11 +81,69 @@ jobs:
if: "matrix.platform != 'windows-latest'"
run: |
RUSTFLAGS="--cfg no_download --cfg cycle_tests" cargo test
- name: Dump kernel OOM messages on failure
if: "failure() && matrix.platform == 'ubuntu-latest'"
run: |
echo "=== dmesg OOM/kill messages ==="
sudo dmesg | grep -iE 'oom|kill|out of memory|invoked oom' || echo "No OOM messages found"
echo "=== dmesg last 50 lines ==="
sudo dmesg | tail -50
- name: Test with UniFFI support on Rust ${{ matrix.toolchain }}
if: "matrix.platform != 'windows-latest' && matrix.build-uniffi"
run: |
RUSTFLAGS="--cfg no_download --cfg cycle_tests" cargo test --features uniffi

stress-test:
strategy:
fail-fast: false
matrix:
shard: [1, 2, 3]
runs-on: ubuntu-latest
steps:
- name: Checkout source code
uses: actions/checkout@v3
- name: Install Rust stable toolchain
run: |
curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh -s -- -y --profile=minimal --default-toolchain stable
- name: Enable caching for bitcoind
id: cache-bitcoind
uses: actions/cache@v4
with:
path: bin/bitcoind-${{ runner.os }}-${{ runner.arch }}
key: bitcoind-${{ runner.os }}-${{ runner.arch }}
- name: Enable caching for electrs
id: cache-electrs
uses: actions/cache@v4
with:
path: bin/electrs-${{ runner.os }}-${{ runner.arch }}
key: electrs-${{ runner.os }}-${{ runner.arch }}
- name: Download bitcoind/electrs
if: "steps.cache-bitcoind.outputs.cache-hit != 'true' || steps.cache-electrs.outputs.cache-hit != 'true'"
run: |
source ./scripts/download_bitcoind_electrs.sh
mkdir bin
mv "$BITCOIND_EXE" bin/bitcoind-${{ runner.os }}-${{ runner.arch }}
mv "$ELECTRS_EXE" bin/electrs-${{ runner.os }}-${{ runner.arch }}
- name: Set bitcoind/electrs environment variables
run: |
echo "BITCOIND_EXE=$( pwd )/bin/bitcoind-${{ runner.os }}-${{ runner.arch }}" >> "$GITHUB_ENV"
echo "ELECTRS_EXE=$( pwd )/bin/electrs-${{ runner.os }}-${{ runner.arch }}" >> "$GITHUB_ENV"
- name: Build integration tests
run: RUSTFLAGS="--cfg no_download --cfg cycle_tests" cargo test --test integration_tests_rust --no-run
- name: Stress-test integration tests (10 iterations)
run: |
for i in $(seq 1 10); do
echo "=== Iteration $i (shard ${{ matrix.shard }}) ==="
RUSTFLAGS="--cfg no_download --cfg cycle_tests" cargo test --test integration_tests_rust -- --nocapture 2>&1 || {
echo "FAILED on iteration $i (shard ${{ matrix.shard }})"
echo "=== dmesg OOM/kill messages ==="
sudo dmesg | grep -iE 'oom|kill|out of memory|invoked oom' || echo "No OOM messages found"
echo "=== dmesg last 50 lines ==="
sudo dmesg | tail -50
exit 1
}
done

doc:
name: Documentation
runs-on: ubuntu-latest
Expand Down
223 changes: 146 additions & 77 deletions tests/common/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -232,7 +232,12 @@ pub(crate) fn setup_bitcoind_and_electrsd() -> (BitcoinD, ElectrsD) {
let mut electrsd_conf = electrsd::Conf::default();
electrsd_conf.http_enabled = true;
electrsd_conf.network = "regtest";
electrsd_conf.view_stderr = true;
let electrsd = ElectrsD::with_conf(electrs_exe, &bitcoind, &electrsd_conf).unwrap();
println!(
"Electrs started with electrum_url={}, esplora_url={:?}",
electrsd.electrum_url, electrsd.esplora_url
);
(bitcoind, electrsd)
}

Expand Down Expand Up @@ -269,9 +274,20 @@ pub(crate) fn random_storage_path() -> PathBuf {
temp_path
}

static NEXT_PORT: AtomicU16 = AtomicU16::new(20000);
static NEXT_PORT: AtomicU16 = AtomicU16::new(0);

fn init_base_port() {
// Initialize once with a random base port. compare_exchange ensures only one thread wins.
// Use a range below the Linux ephemeral port range (32768-60999) to avoid
// collisions with OS-assigned ports used by electrsd/bitcoind.
let base = rng().random_range(10000..30000u16);
let _ = NEXT_PORT.compare_exchange(0, base, Ordering::Relaxed, Ordering::Relaxed);
}

pub(crate) fn generate_listening_addresses() -> Vec<SocketAddress> {
pub(crate) fn random_listening_addresses() -> Vec<SocketAddress> {
// Use an atomic counter to avoid intra-process collisions between parallel tests.
// The base port is randomized once per process to avoid inter-process collisions.
init_base_port();
let port = NEXT_PORT.fetch_add(2, Ordering::Relaxed);
vec![
SocketAddress::TcpIpV4 { addr: [127, 0, 0, 1], port },
Expand Down Expand Up @@ -302,8 +318,8 @@ pub(crate) fn random_config(anchor_channels: bool) -> TestConfig {
println!("Setting random LDK storage dir: {}", rand_dir.display());
node_config.storage_dir_path = rand_dir.to_str().unwrap().to_owned();

let listening_addresses = generate_listening_addresses();
println!("Setting LDK listening addresses: {:?}", listening_addresses);
let listening_addresses = random_listening_addresses();
println!("Setting random LDK listening addresses: {:?}", listening_addresses);
node_config.listening_addresses = Some(listening_addresses);

let alias = random_node_alias();
Expand Down Expand Up @@ -422,81 +438,125 @@ pub(crate) fn setup_two_nodes_with_store(
}

pub(crate) fn setup_node(chain_source: &TestChainSource, config: TestConfig) -> TestNode {
setup_builder!(builder, config.node_config);
match chain_source {
TestChainSource::Esplora(electrsd) => {
let esplora_url = format!("http://{}", electrsd.esplora_url.as_ref().unwrap());
let mut sync_config = EsploraSyncConfig::default();
sync_config.background_sync_config = None;
builder.set_chain_source_esplora(esplora_url.clone(), Some(sync_config));
},
TestChainSource::Electrum(electrsd) => {
let electrum_url = format!("tcp://{}", electrsd.electrum_url);
let mut sync_config = ElectrumSyncConfig::default();
sync_config.background_sync_config = None;
builder.set_chain_source_electrum(electrum_url.clone(), Some(sync_config));
},
TestChainSource::BitcoindRpcSync(bitcoind) => {
let rpc_host = bitcoind.params.rpc_socket.ip().to_string();
let rpc_port = bitcoind.params.rpc_socket.port();
let values = bitcoind.params.get_cookie_values().unwrap().unwrap();
let rpc_user = values.user;
let rpc_password = values.password;
builder.set_chain_source_bitcoind_rpc(rpc_host, rpc_port, rpc_user, rpc_password);
},
TestChainSource::BitcoindRestSync(bitcoind) => {
let rpc_host = bitcoind.params.rpc_socket.ip().to_string();
let rpc_port = bitcoind.params.rpc_socket.port();
let values = bitcoind.params.get_cookie_values().unwrap().unwrap();
let rpc_user = values.user;
let rpc_password = values.password;
let rest_host = bitcoind.params.rpc_socket.ip().to_string();
let rest_port = bitcoind.params.rpc_socket.port();
builder.set_chain_source_bitcoind_rest(
rest_host,
rest_port,
rpc_host,
rpc_port,
rpc_user,
rpc_password,
for attempt in 0..5 {
let mut node_config = config.node_config.clone();
if attempt > 0 {
let new_addrs = random_listening_addresses();
let new_dir = random_storage_path();
println!(
"Retrying with new listening addresses and storage dir (attempt {}): {:?}, {}",
attempt + 1,
new_addrs,
new_dir.display()
);
},
}
node_config.listening_addresses = Some(new_addrs);
node_config.storage_dir_path = new_dir.to_str().unwrap().to_owned();
}

match &config.log_writer {
TestLogWriter::FileWriter => {
builder.set_filesystem_logger(None, None);
},
TestLogWriter::LogFacade => {
builder.set_log_facade_logger();
},
TestLogWriter::Custom(custom_log_writer) => {
builder.set_custom_logger(Arc::clone(custom_log_writer));
},
}
setup_builder!(builder, node_config);
match chain_source {
TestChainSource::Esplora(electrsd) => {
let esplora_url = format!("http://{}", electrsd.esplora_url.as_ref().unwrap());
let mut sync_config = EsploraSyncConfig::default();
sync_config.background_sync_config = None;
builder.set_chain_source_esplora(esplora_url.clone(), Some(sync_config));
},
TestChainSource::Electrum(electrsd) => {
let electrum_url = format!("tcp://{}", electrsd.electrum_url);
let mut sync_config = ElectrumSyncConfig::default();
sync_config.background_sync_config = None;
builder.set_chain_source_electrum(electrum_url.clone(), Some(sync_config));
},
TestChainSource::BitcoindRpcSync(bitcoind) => {
let rpc_host = bitcoind.params.rpc_socket.ip().to_string();
let rpc_port = bitcoind.params.rpc_socket.port();
let values = bitcoind.params.get_cookie_values().unwrap().unwrap();
let rpc_user = values.user;
let rpc_password = values.password;
builder.set_chain_source_bitcoind_rpc(rpc_host, rpc_port, rpc_user, rpc_password);
},
TestChainSource::BitcoindRestSync(bitcoind) => {
let rpc_host = bitcoind.params.rpc_socket.ip().to_string();
let rpc_port = bitcoind.params.rpc_socket.port();
let values = bitcoind.params.get_cookie_values().unwrap().unwrap();
let rpc_user = values.user;
let rpc_password = values.password;
let rest_host = bitcoind.params.rpc_socket.ip().to_string();
let rest_port = bitcoind.params.rpc_socket.port();
builder.set_chain_source_bitcoind_rest(
rest_host,
rest_port,
rpc_host,
rpc_port,
rpc_user,
rpc_password,
);
},
}

builder.set_async_payments_role(config.async_payments_role).unwrap();
match &config.log_writer {
TestLogWriter::FileWriter => {
builder.set_filesystem_logger(None, None);
},
TestLogWriter::LogFacade => {
builder.set_log_facade_logger();
},
TestLogWriter::Custom(custom_log_writer) => {
builder.set_custom_logger(Arc::clone(custom_log_writer));
},
}

if config.recovery_mode {
builder.set_wallet_recovery_mode();
}
builder.set_async_payments_role(config.async_payments_role).unwrap();

let node = match config.store_type {
TestStoreType::TestSyncStore => {
let kv_store = TestSyncStore::new(config.node_config.storage_dir_path.into());
builder.build_with_store(config.node_entropy.into(), kv_store).unwrap()
},
TestStoreType::Sqlite => builder.build(config.node_entropy.into()).unwrap(),
};
if config.recovery_mode {
builder.set_wallet_recovery_mode();
}

if config.recovery_mode {
builder.set_wallet_recovery_mode();
}
let node = match config.store_type {
TestStoreType::TestSyncStore => {
let kv_store = TestSyncStore::new(node_config.storage_dir_path.into());
builder.build_with_store(config.node_entropy.clone().into(), kv_store).unwrap()
},
TestStoreType::Sqlite => builder.build(config.node_entropy.clone().into()).unwrap(),
};

node.start().unwrap();
assert!(node.status().is_running);
assert!(node.status().latest_fee_rate_cache_update_timestamp.is_some());
node
match node.start() {
Ok(()) => {
assert!(node.status().is_running);
assert!(node.status().latest_fee_rate_cache_update_timestamp.is_some());
return node;
},
Err(NodeError::InvalidSocketAddress) => {
if let Some(ref addrs) = node_config.listening_addresses {
for addr in addrs {
if let SocketAddress::TcpIpV4 { port, .. }
| SocketAddress::TcpIpV6 { port, .. } = addr
{
let output = std::process::Command::new("lsof")
.args(["-i", &format!(":{}", port), "-P", "-n"])
.output();
match output {
Ok(o) if !o.stdout.is_empty() => {
eprintln!(
"Port {} is in use:\n{}",
port,
String::from_utf8_lossy(&o.stdout)
);
},
_ => {
eprintln!("Port {} appears unavailable (no lsof info)", port);
},
}
}
}
}
eprintln!("node.start() failed with InvalidSocketAddress, retrying...");
continue;
},
Err(e) => panic!("node.start() failed: {:?}", e),
}
}
panic!("Failed to start node after 5 attempts due to port collisions")
}

pub(crate) async fn generate_blocks_and_wait<E: ElectrumApi>(
Expand All @@ -510,6 +570,9 @@ pub(crate) async fn generate_blocks_and_wait<E: ElectrumApi>(
let address = bitcoind.new_address().expect("failed to get new address");
// TODO: expect this Result once the WouldBlock issue is resolved upstream.
let _block_hashes_res = bitcoind.generate_to_address(num, &address);
if let Err(ref e) = _block_hashes_res {
eprintln!("generate_to_address({}) failed: {:?}", num, e);
}
wait_for_block(electrs, cur_height as usize + num).await;
print!(" Done!");
println!("\n");
Expand All @@ -533,10 +596,14 @@ pub(crate) fn invalidate_blocks(bitcoind: &BitcoindClient, num_blocks: usize) {
pub(crate) async fn wait_for_block<E: ElectrumApi>(electrs: &E, min_height: usize) {
let mut header = match electrs.block_headers_subscribe() {
Ok(header) => header,
Err(_) => {
Err(e) => {
// While subscribing should succeed the first time around, we ran into some cases where
// it didn't. Since we can't proceed without subscribing, we try again after a delay
// and panic if it still fails.
eprintln!("block_headers_subscribe failed (will retry in 3s): {:?}", e);
if let Err(ping_err) = electrs.ping() {
eprintln!("electrs ping also failed: {:?}", ping_err);
}
tokio::time::sleep(Duration::from_secs(3)).await;
electrs.block_headers_subscribe().expect("failed to subscribe to block headers")
},
Expand All @@ -546,8 +613,10 @@ pub(crate) async fn wait_for_block<E: ElectrumApi>(electrs: &E, min_height: usiz
break;
}
header = exponential_backoff_poll(|| {
electrs.ping().expect("failed to ping electrs");
electrs.block_headers_pop().expect("failed to pop block header")
electrs.ping().unwrap_or_else(|e| panic!("failed to ping electrs: {:?}", e));
electrs
.block_headers_pop()
.unwrap_or_else(|e| panic!("failed to pop block header: {:?}", e))
})
.await;
}
Expand All @@ -559,7 +628,7 @@ pub(crate) async fn wait_for_tx<E: ElectrumApi>(electrs: &E, txid: Txid) {
}

exponential_backoff_poll(|| {
electrs.ping().unwrap();
electrs.ping().unwrap_or_else(|e| panic!("failed to ping electrs: {:?}", e));
electrs.transaction_get(&txid).ok()
})
.await;
Expand All @@ -575,7 +644,7 @@ pub(crate) async fn wait_for_outpoint_spend<E: ElectrumApi>(electrs: &E, outpoin
}

exponential_backoff_poll(|| {
electrs.ping().unwrap();
electrs.ping().unwrap_or_else(|e| panic!("failed to ping electrs: {:?}", e));

let is_spent = !electrs.script_get_history(&txout_script).unwrap().is_empty();
is_spent.then_some(())
Expand Down
Loading
Loading