Skip to content

Commit

Permalink
tests: add timestamps to some expect common operations
Browse files Browse the repository at this point in the history
  • Loading branch information
@algorandskiy
algorandskiy committed Aug 19, 2022
1 parent a29e35a commit 452d515
Show file tree
Hide file tree
Showing 2 changed files with 17 additions and 17 deletions.
12 changes: 6 additions & 6 deletions test/e2e-go/cli/goal/expect/catchpointCatchupTest.exp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,7 @@ proc spawnCatchpointCatchupWebProxy { TARGET_ENDPOINT RUNTIME REQUEST_DELAY } {
eof { ::AlgorandGoal::CheckEOF "web proxy failed to start"}
}

puts "Web proxy listening address is $WEBPROXY_LISTEN_ADDRESS"
puts "[clock format [clock seconds] -format %H:%M:%S]: Web proxy listening address is $WEBPROXY_LISTEN_ADDRESS"
return $WEBPROXY_LISTEN_ADDRESS
}

Expand Down Expand Up @@ -105,7 +105,7 @@ if { [catch {
exit 1
}

puts "Primary node listening address is $PRIMARY_LISTEN_ADDRESS"
puts "[clock format [clock seconds] -format %H:%M:%S]: Primary node listening address is $PRIMARY_LISTEN_ADDRESS"

# start the web proxy
set WP_SPAWN_ID 0
Expand All @@ -120,11 +120,11 @@ if { [catch {

set CATCHPOINT [::AlgorandGoal::GetNodeLastCatchpoint $TEST_ROOT_DIR/Primary]

puts "Catchpoint is $CATCHPOINT"
puts "[clock format [clock seconds] -format %H:%M:%S]: Catchpoint is $CATCHPOINT"

regexp -nocase {([0-9]*)#[A-Z2-7]*} $CATCHPOINT CATCHPOINT_ROUND CATCHPOINT_ROUND

puts "Catchpoint round is $CATCHPOINT_ROUND"
puts "[clock format [clock seconds] -format %H:%M:%S]: Catchpoint round is $CATCHPOINT_ROUND"

# wait for the primary to reach $CATCHPOINT_ROUND + 5, so that the catchpoint file would be saved
::AlgorandGoal::WaitForRound [expr {int($CATCHPOINT_ROUND + 5)}] $TEST_ROOT_DIR/Primary
Expand All @@ -138,7 +138,7 @@ if { [catch {
# close the web proxy
close -i $WP_SPAWN_ID

puts "catchpointCatchupTest basic test completed"
puts "[clock format [clock seconds] -format %H:%M:%S]: catchpointCatchupTest basic test completed"

} EXCEPTION ] } {
::AlgorandGoal::Abort "ERROR in catchpointCatchupTest - basic test: $EXCEPTION"
Expand Down Expand Up @@ -191,7 +191,7 @@ if { [catch {

::AlgorandGoal::StopNode $TEST_ROOT_DIR/Primary

puts "catchpointCatchupTest stop/start test completed"
puts "[clock format [clock seconds] -format %H:%M:%S]: catchpointCatchupTest stop/start test completed"
} EXCEPTION ] } {
::AlgorandGoal::Abort "ERROR in catchpointCatchupTest - stop/start: $EXCEPTION"
}
22 changes: 11 additions & 11 deletions test/e2e-go/cli/goal/expect/goalExpectCommon.exp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ package require Tcl 8.0

# Utility method to abort out of this script
proc ::AlgorandGoal::Abort { ERROR } {
puts "Aborting with Error: $ERROR"
puts "[clock format [clock seconds] -format %H:%M:%S]: Aborting with Error: $ERROR"
set LOGS_COLLECTED 0

if { [info exists ::GLOBAL_TEST_ROOT_DIR] } {
Expand Down Expand Up @@ -143,7 +143,7 @@ proc ::AlgorandGoal::StartNode { TEST_ALGO_DIR {SYSTEMD_MANAGED "False"} {PEER_A
set GOAL_PARAMS "$GOAL_PARAMS -p $PEER_ADDRESS"
}
if { [catch {
puts "node start with $TEST_ALGO_DIR"
puts "[clock format [clock seconds] -format %H:%M:%S]: node start with $TEST_ALGO_DIR"
spawn goal {*}$GOAL_PARAMS
if { $SYSTEMD_MANAGED eq "True" } {
expect {
Expand All @@ -170,7 +170,7 @@ proc ::AlgorandGoal::StopNode { TEST_ALGO_DIR {SYSTEMD_MANAGED ""} } {
set timeout 15

if { [catch {
puts "node stop with $TEST_ALGO_DIR"
puts "[clock format [clock seconds] -format %H:%M:%S]: node stop with $TEST_ALGO_DIR"
if { $SYSTEMD_MANAGED eq "" } {
spawn goal node stop -d $TEST_ALGO_DIR
expect {
Expand Down Expand Up @@ -198,7 +198,7 @@ proc ::AlgorandGoal::RestartNode { TEST_ALGO_DIR {SYSTEMD_MANAGED ""} } {
set timeout 30

if { [catch {
puts "node restart with $TEST_ALGO_DIR"
puts "[clock format [clock seconds] -format %H:%M:%S]: node restart with $TEST_ALGO_DIR"
if { $SYSTEMD_MANAGED eq "" } {
spawn goal node restart -d $TEST_ALGO_DIR
expect {
Expand Down Expand Up @@ -247,7 +247,7 @@ proc ::AlgorandGoal::StartNetwork { NETWORK_NAME NETWORK_TEMPLATE TEST_ROOT_DIR

if { [catch {
# Start network
puts "network start $NETWORK_NAME"
puts "[clock format [clock seconds] -format %H:%M:%S]: network start $NETWORK_NAME"
spawn goal network start -r $TEST_ROOT_DIR
expect {
timeout { close; ::AlgorandGoal::Abort "Timed out starting network" }
Expand Down Expand Up @@ -278,7 +278,7 @@ proc ::AlgorandGoal::StartNetwork { NETWORK_NAME NETWORK_TEMPLATE TEST_ROOT_DIR
proc ::AlgorandGoal::StopNetwork { NETWORK_NAME TEST_ROOT_DIR } {
set timeout 60
set NETWORK_STOP_MESSAGE ""
puts "Stopping network: $NETWORK_NAME"
puts "[clock format [clock seconds] -format %H:%M:%S]: Stopping network: $NETWORK_NAME"
spawn goal network stop -r $TEST_ROOT_DIR
expect {
timeout {
Expand Down Expand Up @@ -902,7 +902,7 @@ proc ::AlgorandGoal::GetNodeLastCommittedBlock { NODE_DATA_DIR } {
proc ::AlgorandGoal::StartCatchup { NODE_DATA_DIR CATCHPOINT } {
if { [catch {
# start catchup
puts "spawn node catchup $CATCHPOINT"
puts "[clock format [clock seconds] -format %H:%M:%S]: spawn node catchup $CATCHPOINT"
spawn goal node catchup $CATCHPOINT -d $NODE_DATA_DIR
expect {
timeout { ::AlgorandGoal::Abort "goal node catchup timed out" }
Expand All @@ -920,7 +920,7 @@ proc ::AlgorandGoal::WaitCatchup { TEST_PRIMARY_NODE_DIR WAIT_DURATION_SEC } {
set i 0
while { $i < $WAIT_DURATION_SEC } {
# Check node status
puts "spawn node status "
puts "[clock format [clock seconds] -format %H:%M:%S]: spawn node status "
spawn goal node status -d $TEST_PRIMARY_NODE_DIR
expect {
timeout { ::AlgorandGoal::Abort "goal node status timed out" }
Expand Down Expand Up @@ -979,16 +979,16 @@ proc ::AlgorandGoal::WaitForRound { WAIT_FOR_ROUND_NUMBER NODE_DATA_DIR } {
}
log_user 1
if { $BLOCK > -1 } {
puts "node status check complete, current round is $BLOCK"
puts "[clock format [clock seconds] -format %H:%M:%S]: node status check complete, current round is $BLOCK"
} else {
::AlgorandGoal::Abort "failed to retrieve block round number"
}

# Check if the round number is reached
if { $BLOCK >= $WAIT_FOR_ROUND_NUMBER } {
puts "Reached Round number: $WAIT_FOR_ROUND_NUMBER"; break
puts "[clock format [clock seconds] -format %H:%M:%S]: Reached Round number: $WAIT_FOR_ROUND_NUMBER"; break
} else {
puts "Current Round: '$BLOCK' is less than wait for round: '$WAIT_FOR_ROUND_NUMBER'"
puts "[clock format [clock seconds] -format %H:%M:%S]: Current Round: '$BLOCK' is less than wait for round: '$WAIT_FOR_ROUND_NUMBER'"
if { $LAST_ROUND >= $BLOCK } {
# no progress was made since last time we checked.
incr SLEEP_TIME
Expand Down

0 comments on commit 452d515

Please sign in to comment.