Skip to content

Commit

Permalink
Fix timing issues with version upgrades and other logs
Browse files Browse the repository at this point in the history
  • Loading branch information
teor2345 committed Oct 18, 2023
1 parent 9fb4a5b commit 852e558
Show file tree
Hide file tree
Showing 4 changed files with 55 additions and 39 deletions.
66 changes: 31 additions & 35 deletions zebrad/tests/acceptance.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1849,31 +1849,36 @@ fn lightwalletd_integration_test(test_type: TestType) -> Result<()> {
zebrad.expect_stdout_line_matches("loaded Zebra state cache .*tip.*=.*None")?;
}

// Wait for the state to upgrade, if the upgrade is short.
// Wait for the state to upgrade and the RPC port, if the upgrade is short.
//
// If incompletely upgraded states get written to the CI cache,
// change DATABASE_FORMAT_UPGRADE_IS_LONG to true.
//
// If this line hangs, move it after the lightwalletd launch.
if !DATABASE_FORMAT_UPGRADE_IS_LONG {
if test_type.launches_lightwalletd() && !DATABASE_FORMAT_UPGRADE_IS_LONG {
tracing::info!(
?test_type,
?zebra_rpc_address,
"waiting for zebrad to open its RPC port..."
);
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
[format!(
"Opened RPC endpoint at {}",
zebra_rpc_address.expect("lightwalletd test must have RPC port")
)],
)?;
} else {
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
None,
)?;
}

// Launch lightwalletd, if needed
let lightwalletd_and_port = if test_type.launches_lightwalletd() {
tracing::info!(
?test_type,
?zebra_rpc_address,
"waiting for zebrad to open its RPC port..."
);
zebrad.expect_stdout_line_matches(format!(
"Opened RPC endpoint at {}",
zebra_rpc_address.expect("lightwalletd test must have RPC port")
))?;

tracing::info!(
?zebra_rpc_address,
"launching lightwalletd connected to zebrad",
Expand Down Expand Up @@ -1973,12 +1978,14 @@ fn lightwalletd_integration_test(test_type: TestType) -> Result<()> {
)?;

// Wait for the state to upgrade, if the upgrade is long.
// If this line hangs, change DATABASE_FORMAT_UPGRADE_IS_LONG to false.
// If this line hangs, change DATABASE_FORMAT_UPGRADE_IS_LONG to false,
// or combine "wait for sync" with "wait for state version upgrade".
if DATABASE_FORMAT_UPGRADE_IS_LONG {
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
None,
)?;
}

Expand All @@ -2004,6 +2011,7 @@ fn lightwalletd_integration_test(test_type: TestType) -> Result<()> {
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
None,
)?;
}

Expand Down Expand Up @@ -2730,30 +2738,18 @@ async fn fully_synced_rpc_z_getsubtreesbyindex_snapshot_test() -> Result<()> {
// Store the state version message so we can wait for the upgrade later if needed.
let state_version_message = wait_for_state_version_message(&mut zebrad)?;

// Wait for the state to upgrade, if the upgrade is short.
// If incompletely upgraded states get written to the CI cache,
// change DATABASE_FORMAT_UPGRADE_IS_LONG to true.
if !DATABASE_FORMAT_UPGRADE_IS_LONG {
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
)?;
}
// It doesn't matter how long the state version upgrade takes,
// because the sync finished regex is repeated every minute.
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
None,
)?;

// Wait for zebrad to load the full cached blockchain.
zebrad.expect_stdout_line_matches(SYNC_FINISHED_REGEX)?;

// Wait for the state to upgrade, if the upgrade is long.
// If this line hangs, change DATABASE_FORMAT_UPGRADE_IS_LONG to false.
if DATABASE_FORMAT_UPGRADE_IS_LONG {
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
)?;
}

// Create an http client
let client =
RpcRequestClient::new(zebra_rpc_address.expect("already checked that address is valid"));
Expand Down
17 changes: 14 additions & 3 deletions zebrad/tests/common/cached_state.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
#![allow(dead_code)]

use std::{
iter,
path::{Path, PathBuf},
time::Duration,
};
Expand Down Expand Up @@ -74,31 +75,41 @@ pub fn wait_for_state_version_message<T>(zebrad: &mut TestChild<T>) -> Result<St
}

/// Waits for the `required_version` state upgrade to complete, if needed.
/// If `extra_required_log_regexes` are supplied, also waits for those logs before returning.
///
/// This function should be called with the output of [`wait_for_state_version_message()`].
#[tracing::instrument(skip(zebrad))]
pub fn wait_for_state_version_upgrade<T>(
zebrad: &mut TestChild<T>,
state_version_message: &str,
required_version: Version,
extra_required_log_regexes: impl IntoIterator<Item = String> + std::fmt::Debug,
) -> Result<()> {
if state_version_message.contains("launching upgrade task") {
tracing::info!(
zebrad = ?zebrad.cmd,
%state_version_message,
%required_version,
?extra_required_log_regexes,
"waiting for zebrad state upgrade..."
);

let upgrade_message = zebrad.expect_stdout_line_matches(&format!(
let upgrade_pattern = format!(
"marked database format as upgraded.*format_upgrade_version.*=.*{required_version}"
))?;
);
let extra_required_log_regexes = extra_required_log_regexes.into_iter();
let required_logs: Vec<String> = iter::once(upgrade_pattern)
.chain(extra_required_log_regexes)
.collect();

let upgrade_messages = zebrad.expect_stdout_line_matches_all_unordered(&required_logs)?;

tracing::info!(
zebrad = ?zebrad.cmd,
%state_version_message,
%required_version,
%upgrade_message,
?required_logs,
?upgrade_messages,
"zebrad state has been upgraded"
);
}
Expand Down
8 changes: 8 additions & 0 deletions zebrad/tests/common/checkpoints.rs
Original file line number Diff line number Diff line change
Expand Up @@ -87,12 +87,19 @@ pub async fn run(network: Network) -> Result<()> {

// Before we write a cached state image, wait for a database upgrade.
//
// It is ok if the logs are in the wrong order and the test sometimes fails,
// because testnet is unreliable anyway.
//
// TODO: this line will hang if the state upgrade is slower than the RPC server spawn.
// But that is unlikely, because both 25.1 and 25.2 are quick on testnet.
//
// TODO: combine this check with the CHECKPOINT_VERIFIER_REGEX and RPC endpoint checks.
// This is tricky because we need to get the last checkpoint log.
wait_for_state_version_upgrade(
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
None,
)?;
}

Expand All @@ -105,6 +112,7 @@ pub async fn run(network: Network) -> Result<()> {
);

let last_checkpoint = zebrad.expect_stdout_line_matches(CHECKPOINT_VERIFIER_REGEX)?;

// TODO: do this with a regex?
let (_prefix, last_checkpoint) = last_checkpoint
.split_once("max_checkpoint_height")
Expand Down
3 changes: 2 additions & 1 deletion zebrad/tests/common/lightwalletd/wallet_grpc_test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -110,7 +110,6 @@ pub async fn run() -> Result<()> {
?zebra_rpc_address,
"launched zebrad, waiting for zebrad to open its RPC port..."
);
zebrad.expect_stdout_line_matches(&format!("Opened RPC endpoint at {zebra_rpc_address}"))?;

// Wait for the state to upgrade, if the upgrade is short.
//
Expand All @@ -124,6 +123,7 @@ pub async fn run() -> Result<()> {
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
[format!("Opened RPC endpoint at {zebra_rpc_address}")],
)?;
}

Expand Down Expand Up @@ -160,6 +160,7 @@ pub async fn run() -> Result<()> {
&mut zebrad,
&state_version_message,
database_format_version_in_code(),
None,
)?;
}

Expand Down

0 comments on commit 852e558

Please sign in to comment.