diff --git a/tests/integration/replication.tcl b/tests/integration/replication.tcl index 7c03c4bc6..d47ec4fe4 100644 --- a/tests/integration/replication.tcl +++ b/tests/integration/replication.tcl @@ -430,6 +430,7 @@ test {diskless loading short read} { } # Start the replication process... + set loglines [count_log_lines -1] $master config set repl-diskless-sync-delay 0 $replica replicaof $master_host $master_port @@ -439,7 +440,7 @@ test {diskless loading short read} { for {set i 0} {$i < $attempts} {incr i} { # wait for the replica to start reading the rdb # using the log file since the replica only responds to INFO once in 2mb - wait_for_log_message -1 "*Loading DB in memory*" 5 2000 1 + wait_for_log_message -1 "*Loading DB in memory*" $loglines 2000 1 # add some additional random sleep so that we kill the master on a different place each time after [expr {int(rand()*100)}] @@ -448,7 +449,7 @@ test {diskless loading short read} { set killed [$master client kill type replica] if {[catch { - set res [wait_for_log_message -1 "*Internal error in RDB*" 5 100 10] + set res [wait_for_log_message -1 "*Internal error in RDB*" $loglines 100 10] if {$::verbose} { puts $res } @@ -461,6 +462,7 @@ test {diskless loading short read} { $master config set repl-backlog-size [expr {16384 + $i}] } # wait for loading to stop (fail) + set loglines [count_log_lines -1] wait_for_condition 100 10 { [s -1 loading] eq 0 } else { @@ -535,6 +537,7 @@ start_server {tags {"repl"}} { # start replication # it's enough for just one replica to be slow, and have it's write handler enabled # so that the whole rdb generation process is bound to that + set loglines [count_log_lines -1] [lindex $replicas 0] config set repl-diskless-load swapdb [lindex $replicas 0] config set key-load-delay 100 [lindex $replicas 0] replicaof $master_host $master_port @@ -542,7 +545,7 @@ start_server {tags {"repl"}} { # wait for the replicas to start reading the rdb # using the log file since the replica only responds to INFO once in 2mb - wait_for_log_message -1 "*Loading DB in memory*" 8 800 10 + wait_for_log_message -1 "*Loading DB in memory*" $loglines 800 10 if {$measure_time} { set master_statfile "/proc/$master_pid/stat" @@ -558,6 +561,7 @@ start_server {tags {"repl"}} { $master incr $all_drop # disconnect replicas depending on the current test + set loglines [count_log_lines -2] if {$all_drop == "all" || $all_drop == "fast"} { exec kill [srv 0 pid] set replicas_alive [lreplace $replicas_alive 1 1] @@ -576,13 +580,13 @@ start_server {tags {"repl"}} { # make sure we got what we were aiming for, by looking for the message in the log file if {$all_drop == "all"} { - wait_for_log_message -2 "*Diskless rdb transfer, last replica dropped, killing fork child*" 12 1 1 + wait_for_log_message -2 "*Diskless rdb transfer, last replica dropped, killing fork child*" $loglines 1 1 } if {$all_drop == "no"} { - wait_for_log_message -2 "*Diskless rdb transfer, done reading from pipe, 2 replicas still up*" 12 1 1 + wait_for_log_message -2 "*Diskless rdb transfer, done reading from pipe, 2 replicas still up*" $loglines 1 1 } if {$all_drop == "slow" || $all_drop == "fast"} { - wait_for_log_message -2 "*Diskless rdb transfer, done reading from pipe, 1 replicas still up*" 12 1 1 + wait_for_log_message -2 "*Diskless rdb transfer, done reading from pipe, 1 replicas still up*" $loglines 1 1 } # make sure we don't have a busy loop going thought epoll_wait diff --git a/tests/support/util.tcl b/tests/support/util.tcl index 8bec95374..fce3ffd18 100644 --- a/tests/support/util.tcl +++ b/tests/support/util.tcl @@ -99,11 +99,27 @@ proc wait_for_ofs_sync {r1 r2} { } } -proc wait_for_log_message {srv_idx pattern last_lines maxtries delay} { +# count current log lines in server's stdout +proc count_log_lines {srv_idx} { + set _ [exec wc -l < [srv $srv_idx stdout]] +} + +# verify pattern exists in server's sdtout after a certain line number +proc verify_log_message {srv_idx pattern from_line} { + set lines_after [count_log_lines] + set lines [expr $lines_after - $from_line] + set result [exec tail -$lines < [srv $srv_idx stdout]] + if {![string match $pattern $result]} { + error "assertion:expected message not found in log file: $pattern" + } +} + +# wait for pattern to be found in server's stdout after certain line number +proc wait_for_log_message {srv_idx pattern from_line maxtries delay} { set retry $maxtries set stdout [srv $srv_idx stdout] while {$retry} { - set result [exec tail -$last_lines < $stdout] + set result [exec tail +$from_line < $stdout] set result [split $result "\n"] foreach line $result { if {[string match $pattern $line]} { @@ -114,7 +130,7 @@ proc wait_for_log_message {srv_idx pattern last_lines maxtries delay} { after $delay } if {$retry == 0} { - fail "log message of '$pattern' not found" + fail "log message of '$pattern' not found in $stdout after line: $from_line" } } diff --git a/tests/unit/moduleapi/testrdb.tcl b/tests/unit/moduleapi/testrdb.tcl index a93b34b69..98641ae0a 100644 --- a/tests/unit/moduleapi/testrdb.tcl +++ b/tests/unit/moduleapi/testrdb.tcl @@ -67,6 +67,7 @@ tags "modules" { } # Start the replication process... + set loglines [count_log_lines -1] $master config set repl-diskless-sync-delay 0 $replica replicaof $master_host $master_port @@ -76,7 +77,7 @@ tags "modules" { for {set i 0} {$i < $attempts} {incr i} { # wait for the replica to start reading the rdb # using the log file since the replica only responds to INFO once in 2mb - wait_for_log_message -1 "*Loading DB in memory*" 5 2000 1 + wait_for_log_message -1 "*Loading DB in memory*" $loglines 2000 1 # add some additional random sleep so that we kill the master on a different place each time after [expr {int(rand()*100)}] @@ -85,7 +86,7 @@ tags "modules" { set killed [$master client kill type replica] if {[catch { - set res [wait_for_log_message -1 "*Internal error in RDB*" 5 100 10] + set res [wait_for_log_message -1 "*Internal error in RDB*" $loglines 100 10] if {$::verbose} { puts $res } @@ -98,6 +99,7 @@ tags "modules" { $master config set repl-backlog-size [expr {16384 + $i}] } # wait for loading to stop (fail) + set loglines [count_log_lines -1] wait_for_condition 100 10 { [s -1 loading] eq 0 } else {