Merge pull request #38728 from azat/expect-tests-debug

Add exp_internal for expect tests

tests/clickhouse-test

@@ -499,6 +499,7 @@ class TestCase:
             database = testcase_args.database
             os.environ.setdefault("CLICKHOUSE_DATABASE", database)
             os.environ.setdefault("CLICKHOUSE_TMP", suite_tmp_dir)
+            testcase_args.test_tmp_dir = suite_tmp_dir
         else:
             # If --database is not specified, we will create temporary database with
             # unique name and we will recreate and drop it for each test
@@ -529,6 +530,16 @@ class TestCase:
 
         testcase_args.testcase_database = database
 
+        # Printed only in case of failures
+        #
+        # NOTE: here we use "CLICKHOUSE_TMP" instead of "file_suffix",
+        # so it is installed in configure_testcase_args() unlike other files
+        # (stdout_file, stderr_file) in TestCase::__init__().
+        # Since using CLICKHOUSE_TMP is easier to use in expect.
+        testcase_args.debug_log_file = (
+            os.path.join(testcase_args.test_tmp_dir, testcase_basename) + ".debuglog"
+        )
+
         return testcase_args
 
     def cli_random_settings(self) -> str:
@@ -699,7 +710,7 @@ class TestCase:
 
         return None
 
-    def process_result_impl(self, proc, stdout: str, stderr: str, total_time: float):
+    def process_result_impl(self, proc, stdout: str, stderr: str, debug_log: str, total_time: float):
         description = ""
 
         if proc:
@@ -712,6 +723,9 @@ class TestCase:
 
                 if stderr:
                     description += stderr
+                if debug_log:
+                    description += "\n"
+                    description += debug_log
                 return TestResult(
                     self.name,
                     TestStatus.FAIL,
@@ -727,6 +741,9 @@ class TestCase:
                 if stderr:
                     description += "\n"
                     description += stderr
+                if debug_log:
+                    description += "\n"
+                    description += debug_log
 
                 # Stop on fatal errors like segmentation fault. They are sent to client via logs.
                 if " <Fatal> " in stderr:
@@ -757,6 +774,9 @@ class TestCase:
         if stderr:
             description += "\n{}\n".format("\n".join(stderr.splitlines()[:100]))
             description += f"\nstdout:\n{stdout}\n"
+            if debug_log:
+                description += "\n"
+                description += debug_log
             return TestResult(
                 self.name,
                 TestStatus.FAIL,
@@ -767,6 +787,9 @@ class TestCase:
 
         if "Exception" in stdout:
             description += "\n{}\n".format("\n".join(stdout.splitlines()[:100]))
+            if debug_log:
+                description += "\n"
+                description += debug_log
             return TestResult(
                 self.name,
                 TestStatus.FAIL,
@@ -813,6 +836,9 @@ class TestCase:
                 universal_newlines=True,
             ).communicate()[0]
             description += f"\n{diff}\n"
+            if debug_log:
+                description += "\n"
+                description += debug_log
             return TestResult(
                 self.name,
                 TestStatus.FAIL,
@@ -826,6 +852,9 @@ class TestCase:
             and total_time > 60
             and "long" not in self.tags
         ):
+            if debug_log:
+                description += "\n"
+                description += debug_log
             # We're in Flaky Check mode, check the run time as well while we're at it.
             return TestResult(
                 self.name,
@@ -839,6 +868,8 @@ class TestCase:
             os.remove(self.stdout_file)
         if os.path.exists(self.stderr_file):
             os.remove(self.stderr_file)
+        if os.path.exists(self.testcase_args.debug_log_file):
+            os.remove(self.testcase_args.debug_log_file)
 
         return TestResult(self.name, TestStatus.OK, None, total_time, description)
 
@@ -872,7 +903,7 @@ class TestCase:
 
     def run_single_test(
         self, server_logs_level, client_options
-    ) -> Tuple[Optional[Popen], str, str, float]:
+    ) -> Tuple[Optional[Popen], str, str, str, float]:
         args = self.testcase_args
         client = args.testcase_client
         start_time = args.testcase_start_time
@@ -922,6 +953,13 @@ class TestCase:
             )
             need_drop_database = not maybe_passed
 
+        debug_log = ""
+        if os.path.exists(self.testcase_args.debug_log_file):
+            with open(self.testcase_args.debug_log_file, "rb") as stream:
+                debug_log += self.testcase_args.debug_log_file + ":\n"
+                debug_log += str(stream.read(), errors="replace", encoding="utf-8")
+                debug_log += "\n"
+
         if need_drop_database:
             seconds_left = max(
                 args.timeout - (datetime.now() - start_time).total_seconds(), 20
@@ -941,6 +979,7 @@ class TestCase:
                     None,
                     "",
                     f"Timeout dropping database {database} after test",
+                    debug_log,
                     total_time,
                 )
             shutil.rmtree(args.test_tmp_dir)
@@ -964,12 +1003,13 @@ class TestCase:
         if os.path.exists(self.stdout_file):
             with open(self.stdout_file, "rb") as stdfd:
                 stdout = str(stdfd.read(), errors="replace", encoding="utf-8")
+
         stderr = ""
         if os.path.exists(self.stderr_file):
             with open(self.stderr_file, "rb") as stdfd:
-                stderr = str(stdfd.read(), errors="replace", encoding="utf-8")
+                stderr += str(stdfd.read(), errors="replace", encoding="utf-8")
 
-        return proc, stdout, stderr, total_time
+        return proc, stdout, stderr, debug_log, total_time
 
     def run(self, args, suite, client_options, server_logs_level):
         try:
@@ -994,11 +1034,11 @@ class TestCase:
                 args, self.case_file, suite.suite_tmp_path
             )
             client_options = self.add_random_settings(args, client_options)
-            proc, stdout, stderr, total_time = self.run_single_test(
+            proc, stdout, stderr, debug_log, total_time = self.run_single_test(
                 server_logs_level, client_options
             )
 
-            result = self.process_result_impl(proc, stdout, stderr, total_time)
+            result = self.process_result_impl(proc, stdout, stderr, debug_log, total_time)
             result.check_if_need_retry(args, stdout, stderr, self.runs_count)
             if result.status == TestStatus.FAIL:
                 result.description = self.add_info_about_settings(

tests/queries/0_stateless/01176_mysql_client_interactive.expect

@@ -2,6 +2,10 @@
 # Tags: no-fasttest
 # Tag no-fasttest: requires mysql client
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -13,7 +17,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$MYSQL_CLIENT_BINARY \$MYSQL_CLIENT_OPT"
 expect -nocase -re "mysql.*> "
 

tests/queries/0_stateless/01179_insert_values_semicolon.expect

@@ -1,6 +1,10 @@
 #!/usr/bin/expect -f
 # Tags: long
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -11,7 +15,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/01180_client_syntax_errors.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/01293_client_interactive_vertical_multiline.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 10
 match_max 100000
@@ -14,7 +18,6 @@ expect_after {
 # useful debugging configuration
 # exp_internal 1
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/01293_client_interactive_vertical_singleline.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/01300_client_save_history_when_terminated_long.expect

@@ -1,6 +1,10 @@
 #!/usr/bin/expect -f
 # Tags: long
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     # A default timeout action is to do nothing, change it to fail
     timeout { exit 1 }
 }
-set basedir [file dirname $argv0]
 
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "

tests/queries/0_stateless/01370_client_autocomplete_word_break_characters.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT"
 expect ":) "
 

tests/queries/0_stateless/01520_client_print_query_id.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/01565_reconnect_after_client_error.expect

@@ -4,6 +4,10 @@
 # This is a separate test, because we want to test the interactive mode.
 # https://github.com/ClickHouse/ClickHouse/issues/19353
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -15,7 +19,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion -mn"
 expect "\n:) "
 

tests/queries/0_stateless/01755_client_highlight_multi_line_comment_regression.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/01910_client_replxx_container_overflow_long.expect

@@ -1,6 +1,10 @@
 #!/usr/bin/expect -f
 # Tags: long
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     # A default timeout action is to do nothing, change it to fail
     timeout { exit 1 }
 }
-set basedir [file dirname $argv0]
 
 # history file is not required, in-memory history is enough
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --history_file=$basedir/01910_client_replxx_container_overflow_long.history.log"

tests/queries/0_stateless/01933_client_replxx_convert_history.expect

@@ -2,6 +2,10 @@
 # Tags: no-parallel
 # Tag no-parallel: Uses non unique history file
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -11,7 +15,6 @@ expect_after {
     # A default timeout action is to do nothing, change it to fail
     timeout { exit 1 }
 }
-set basedir [file dirname $argv0]
 
 exec bash -c "echo select 1 > $argv0.txt"
 exec bash -c "echo select 1 >> $argv0.txt"

tests/queries/0_stateless/01945_show_debug_warning.expect

@@ -3,6 +3,10 @@
 # This is a test for system.warnings. Testing in interactive mode is necessary,
 # as we want to see certain warnings from client
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -14,7 +18,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 set Debug_type 0
 
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"

tests/queries/0_stateless/02003_memory_limit_in_client.expect

@@ -4,6 +4,10 @@
 # This is a test for system.warnings. Testing in interactive mode is necessary,
 # as we want to see certain warnings from client
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -15,8 +19,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
-
 #
 # Check that the query will fail in clickhouse-client
 #

tests/queries/0_stateless/02047_client_exception.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 20
 match_max 100000
@@ -11,7 +15,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/02049_clickhouse_local_merge_tree.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 20
 match_max 100000
@@ -11,7 +15,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_LOCAL  --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/02105_backslash_letter_commands.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 02
 match_max 100000
@@ -10,7 +14,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 expect ":) "
 

tests/queries/0_stateless/02112_delayed_clickhouse_client_with_queries_file.expect

@@ -1,6 +1,10 @@
 #!/usr/bin/expect -f
 # Tags: no-parallel
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 20
 match_max 100000
@@ -12,8 +16,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
-
 system "$basedir/helpers/02112_prepare.sh"
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT --disable_suggestion --interactive --queries-file $basedir/file_02112"
 expect ":) "

tests/queries/0_stateless/02112_delayed_clickhouse_local.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 20
 match_max 100000
@@ -11,7 +15,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_LOCAL --disable_suggestion --interactive --query 'create table t(i Int32) engine=Memory; insert into t select 1'"
 expect ":) "
 

tests/queries/0_stateless/02112_delayed_clickhouse_local_with_queries_file.expect

@@ -1,6 +1,10 @@
 #!/usr/bin/expect -f
 # Tags: no-parallel
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 20
 match_max 100000
@@ -12,8 +16,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
-
 system "$basedir/helpers/02112_prepare.sh"
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_LOCAL --disable_suggestion --interactive --queries-file $basedir/file_02112"
 expect ":) "

tests/queries/0_stateless/02116_interactive_hello.expect

@@ -1,6 +1,10 @@
 #!/usr/bin/expect -f
 # Tags: long
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 match_max 100000
@@ -12,7 +16,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion"
 
 expect -re "ClickHouse client version \[\\d\]{2}.\[\\d\]{1,2}.\[\\d\]{1,2}.\[\\d\]{1,2}.\r"

tests/queries/0_stateless/02132_client_history_navigation.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 3
 match_max 100000
@@ -14,7 +18,6 @@ expect_after {
 # useful debugging configuration
 # exp_internal 1
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT --disable_suggestion --highlight 0"
 expect ":) "
 

tests/queries/0_stateless/02160_client_autocomplete_parse_query.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 60
 set uuid ""
@@ -11,7 +15,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_CLIENT_BINARY \$CLICKHOUSE_CLIENT_OPT"
 expect ":) "
 

tests/queries/0_stateless/02164_clickhouse_local_interactive_exception.expect

@@ -1,5 +1,9 @@
 #!/usr/bin/expect -f
 
+set basedir [file dirname $argv0]
+set basename [file tail $argv0]
+exp_internal -f $env(CLICKHOUSE_TMP)/$basename.debuglog 0
+
 log_user 0
 set timeout 20
 match_max 100000
@@ -9,7 +13,6 @@ expect_after {
     timeout { exit 1 }
 }
 
-set basedir [file dirname $argv0]
 spawn bash -c "source $basedir/../shell_config.sh ; \$CLICKHOUSE_LOCAL  --disable_suggestion"
 
 expect ":) "

utils/check-style/check-style

@@ -314,6 +314,12 @@ for test_case in "${tests_with_event_time_date[@]}"; do
     }
 done
 
+expect_tests=( $(find $ROOT_PATH/tests/queries -name '*.expect') )
+for test_case in "${expect_tests[@]}"; do
+    pattern="^exp_internal -f \$env(CLICKHOUSE_TMP)/\$basename.debuglog 0$"
+    grep -q "$pattern" "$test_case" || echo "Missing '$pattern' in '$test_case'"
+done
+
 # Conflict markers
 find $ROOT_PATH/{src,base,programs,utils,tests,docs,website,cmake} -name '*.md' -or -name '*.cpp' -or -name '*.h' |
     xargs grep -P '^(<<<<<<<|=======|>>>>>>>)$' | grep -P '.' && echo "Conflict markers are found in files"