stabilize tests that look for log lines (#7367)

tests were sensitive to additional log lines appearing in the log
causing the search to come empty handed.

instead of just looking for the n last log lines, capture the log lines
before performing the action, and then search from that offset.

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

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"
     }
 }
 

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 {