From bb5d813e5c4ffa0315f0b16ca0a2f06195d884fd Mon Sep 17 00:00:00 2001
From: Xin Hao Zhang <xzhang@cockroachlabs.com>
Date: Tue, 25 Jul 2023 15:10:27 -0400
Subject: [PATCH] acceptance: make `TestDockerCLI_test_exec_log` wait for
 unambiguous log line

The `TestDockerCLI_test_exec_log` test had a section where it
waits for the last executed stmt to appear in the exec_log file
before proceeding to the next section. This is done by grep'ing
the query string of the last stmt. This works fine most of the time,
 however, the 2nd last and last stmt executed happen to have the same
query string, so it's possible that we are only seeing the 2nd to last
stmt in the log. This can cause the test to fail as in the next section,
we expect all query logs to be present in the file.

This commit fixes this by issuing a distinct query as the last query
so that we can grep for a distinct query string to verify all stmts
should have been written.

A new proc is also added to `common.tcl`:
flush_and_sync_logs is a proc that takes 2 arguments, `filename` and
`grep_text`. It will trigger a signal hang up to trigger a log flush
and then attempt to find the `grep_text` in the specified file.

Epic: none
Fixes: #106367
---
 pkg/cli/interactive_tests/common.tcl        | 14 ++++++++++++
 pkg/cli/interactive_tests/test_exec_log.tcl | 24 +++++++--------------
 2 files changed, 22 insertions(+), 16 deletions(-)

diff --git a/pkg/cli/interactive_tests/common.tcl b/pkg/cli/interactive_tests/common.tcl
index 38fc46d70c54..2d49cb5b5c44 100644
--- a/pkg/cli/interactive_tests/common.tcl
+++ b/pkg/cli/interactive_tests/common.tcl
@@ -144,6 +144,20 @@ proc flush_server_logs {} {
     report "END FLUSH LOGS"
 }
 
+proc flush_and_sync_logs {filename grep_text} {
+    report "BEGIN FLUSH LOGS $filename"
+    system "kill -HUP `cat server_pid` 2>/dev/null"
+    # Wait for flush to occur.
+    system "for i in `seq 1 5`; do
+              grep '$grep_text' $filename && exit 0;
+              echo still waiting
+              sleep 1
+            done
+            echo 'server failed to flush logs?'
+            exit 1"
+    report "END FLUSH LOGS"
+}
+
 proc force_stop_server {argv} {
     report "BEGIN FORCE STOP SERVER"
     system "kill -KILL `cat server_pid`"
diff --git a/pkg/cli/interactive_tests/test_exec_log.tcl b/pkg/cli/interactive_tests/test_exec_log.tcl
index 8d3852db7f5e..f1f0d01f28fa 100644
--- a/pkg/cli/interactive_tests/test_exec_log.tcl
+++ b/pkg/cli/interactive_tests/test_exec_log.tcl
@@ -97,23 +97,15 @@ send "SELECT 550+5;\r"
 eexpect 555
 eexpect root@
 
-flush_server_logs
+# Use this distinct query to be the boundary - if we see this stmt in the
+# exec log, then we should expect all the previous statements in the log too.
+
+send "SELECT 111;\r"
+eexpect 111
+eexpect root@
+
+flush_and_sync_logs $logfile "SELECT ..*111..*"
 
-# Now check the items are there in the log file. We need to iterate
-# because flush_server_logs only syncs on flush of cockroach.log, not
-# the exec log.
-#
-# We also check the last statement first, this ensures that every
-# previous statement is also in the log file after this check
-# succeeds.
-system "for i in `seq 1 3`; do
-  grep 'SELECT ..*550..* +' $logfile && exit 0;
-  echo still waiting;
-  sleep 1;
-done;
-echo 'not finding two separate txn counter values?';
-grep 'SELECT ..*550..* +' $logfile;
-exit 1;"
 
 # Two separate single-stmt txns.
 system "n=`grep 'SELECT ..*550..* +' $logfile | sed -e 's/.*TxnCounter.:\\(\[0-9\]*\\).*/\\1/g' | uniq | wc -l`; if test \$n -ne 2; then echo unexpected \$n; exit 1; fi"