From 9e77365d77a4f3d961e360706fd0a84f3506db42 Mon Sep 17 00:00:00 2001 From: Brian Neradt Date: Wed, 8 Feb 2023 16:49:29 +0000 Subject: [PATCH] Make autest ts shutdown tests more reliable This is a second iteration to further improve some of the autests that exercise ATS shutting down during test execution. See #9372 for the previous patch. The previous update improved reliability, but still had a race condition between autest recognizing ATS process shutdown and ATS writing the expected error log. If it detected the ts process ending before the log was written, the autest would fail because the framework thought the process ended before the Ready condition was satisfied. This patch addresses this by using a separate process to wait upon the log entry instead of making the ts Ready condition the content of the log file. --- .../remap/remap_load_empty_failure.test.py | 14 ++++++++++++-- tests/gold_tests/shutdown/emergency.test.py | 17 +++++++++++++---- tests/gold_tests/shutdown/fatal.test.py | 17 +++++++++++++---- 3 files changed, 38 insertions(+), 10 deletions(-) diff --git a/tests/gold_tests/remap/remap_load_empty_failure.test.py b/tests/gold_tests/remap/remap_load_empty_failure.test.py index 199d65da778..47a1b494d24 100644 --- a/tests/gold_tests/remap/remap_load_empty_failure.test.py +++ b/tests/gold_tests/remap/remap_load_empty_failure.test.py @@ -24,9 +24,19 @@ ts.Disk.remap_config.AddLine(f"") # empty file ts.Disk.records_config.update({'proxy.config.url_remap.min_rules_required': 1}) ts.ReturnCode = 33 # expect to Emergency fail due to empty "remap.config". -ts.Ready = When.FileContains(ts.Disk.diags_log.Name, "remap.config failed to load") +ts.Ready = 0 tr = Test.AddTestRun("test") + +# We have to wait upon TS to emit the expected log message, but it cannot be +# the ts Ready criteria because autest might detect the process going away +# before it detects the log message. So we add a separate process that waits +# upon the log message. +watcher = Test.Processes.Process("watcher") +watcher.Command = "sleep 1" +watcher.Ready = When.FileContains(ts.Disk.diags_log.Name, "remap.config failed to load") +watcher.StartBefore(ts) + tr.Processes.Default.Command = "echo howdy" tr.TimeOut = 5 -tr.Processes.Default.StartBefore(ts) +tr.Processes.Default.StartBefore(watcher) diff --git a/tests/gold_tests/shutdown/emergency.test.py b/tests/gold_tests/shutdown/emergency.test.py index 74ca0f9791d..3f4a8027c00 100644 --- a/tests/gold_tests/shutdown/emergency.test.py +++ b/tests/gold_tests/shutdown/emergency.test.py @@ -40,14 +40,23 @@ # Load plugin Test.PrepareTestPlugin(os.path.join(Test.Variables.AtsTestPluginsDir, 'emergency_shutdown.so'), ts) -# www.example.com Host tr = Test.AddTestRun() + +# We have to wait upon TS to emit the expected log message, but it cannot be +# the ts Ready criteria because autest might detect the process going away +# before it detects the log message. So we add a separate process that waits +# upon the log message. +watcher = Test.Processes.Process("watcher") +watcher.Command = "sleep 1" +watcher.Ready = When.FileContains(ts.Disk.diags_log.Name, "testing emergency shutdown") +watcher.StartBefore(ts) + tr.Processes.Default.Command = 'printf "Emergency Shutdown Test"' tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.StartBefore(ts) -tr.Timeout = 5 +tr.Processes.Default.StartBefore(watcher) +tr.Timeout = 5 ts.ReturnCode = 33 -ts.Ready = When.FileContains(ts.Disk.traffic_out.Name, "testing emergency shutdown") +ts.Ready = 0 ts.Disk.traffic_out.Content = Testers.ExcludesExpression('failed to shutdown', 'should NOT contain "failed to shutdown"') ts.Disk.diags_log.Content = Testers.IncludesExpression('testing emergency shutdown', 'should contain "testing emergency shutdown"') diff --git a/tests/gold_tests/shutdown/fatal.test.py b/tests/gold_tests/shutdown/fatal.test.py index da7999d8da0..258876e193a 100644 --- a/tests/gold_tests/shutdown/fatal.test.py +++ b/tests/gold_tests/shutdown/fatal.test.py @@ -40,14 +40,23 @@ # Load plugin Test.PrepareTestPlugin(os.path.join(Test.Variables.AtsTestPluginsDir, 'fatal_shutdown.so'), ts) -# www.example.com Host tr = Test.AddTestRun() + +# We have to wait upon TS to emit the expected log message, but it cannot be +# the ts Ready criteria because autest might detect the process going away +# before it detects the log message. So we add a separate process that waits +# upon the log message. +watcher = Test.Processes.Process("watcher") +watcher.Command = "sleep 1" +watcher.Ready = When.FileContains(ts.Disk.diags_log.Name, "testing fatal shutdown") +watcher.StartBefore(ts) + tr.Processes.Default.Command = 'printf "Fatal Shutdown Test"' tr.Processes.Default.ReturnCode = 0 -tr.Processes.Default.StartBefore(ts) -tr.Timeout = 5 +tr.Processes.Default.StartBefore(watcher) +tr.Timeout = 5 ts.ReturnCode = 70 -ts.Ready = When.FileContains(ts.Disk.traffic_out.Name, "testing fatal shutdown") +ts.Ready = 0 ts.Disk.traffic_out.Content = Testers.ExcludesExpression('failed to shutdown', 'should NOT contain "failed to shutdown"') ts.Disk.diags_log.Content = Testers.IncludesExpression('testing fatal shutdown', 'should contain "testing fatal shutdown"')