From cd14573bf0d6b0eeda5cd423a610811f144fdd25 Mon Sep 17 00:00:00 2001 From: bneradt Date: Wed, 25 Mar 2026 12:52:54 -0500 Subject: [PATCH] sigusr2 autest: simplify Process and Ready objects Rewrite the sigusr2 autest to drive each scenario from a single shell helper script instead of a chain of AuTest Processes. This removes the Ready-condition races from the old test, keeps the signal and log rotation ordering in one place, and makes the log file expectations easier to follow. This should address flakiness in the test that has been seen in CI. --- tests/gold_tests/logging/sigusr2.test.py | 263 +++++++----------- .../logging/sigusr2_rotate_custom_log.sh | 101 +++++++ .../logging/sigusr2_rotate_diags.sh | 79 ++++++ 3 files changed, 281 insertions(+), 162 deletions(-) create mode 100644 tests/gold_tests/logging/sigusr2_rotate_custom_log.sh create mode 100644 tests/gold_tests/logging/sigusr2_rotate_diags.sh diff --git a/tests/gold_tests/logging/sigusr2.test.py b/tests/gold_tests/logging/sigusr2.test.py index 397119ab2b5..67f85c5a27f 100644 --- a/tests/gold_tests/logging/sigusr2.test.py +++ b/tests/gold_tests/logging/sigusr2.test.py @@ -18,9 +18,12 @@ # limitations under the License. import os +import shlex import sys TS_PID_SCRIPT = 'ts_process_handler.py' +ROTATE_DIAGS_SCRIPT = 'sigusr2_rotate_diags.sh' +ROTATE_CUSTOM_LOG_SCRIPT = 'sigusr2_rotate_custom_log.sh' class Sigusr2Test: @@ -29,17 +32,29 @@ class Sigusr2Test: """ __ts_counter = 1 - __server = None - - def __init__(self): - self.server = self.__configure_server() - self.ts = self.__configure_traffic_server() - - def __configure_traffic_server(self): - self._ts_name = "sigusr2_ts{}".format(Sigusr2Test.__ts_counter) - Sigusr2Test.__ts_counter += 1 - self.ts = Test.MakeATSProcess(self._ts_name) - self.ts.Disk.records_config.update( + __server_counter = 1 + + @classmethod + def _next_ts_name(cls): + ts_name = f"sigusr2_ts{cls.__ts_counter}" + cls.__ts_counter += 1 + return ts_name + + @classmethod + def _next_server_name(cls): + server_name = f"sigusr2_server{cls.__server_counter}" + cls.__server_counter += 1 + return server_name + + @staticmethod + def _make_script_command(script_name, *args): + quoted_args = ' '.join(shlex.quote(str(arg)) for arg in args) + return f"bash ./{script_name} {quoted_args}" + + def _configure_traffic_server(self, tr): + ts_name = self._next_ts_name() + ts = tr.MakeATSProcess(ts_name) + ts.Disk.records_config.update( { 'proxy.config.http.wait_for_cache': 1, 'proxy.config.diags.debug.enabled': 1, @@ -50,18 +65,54 @@ def __configure_traffic_server(self): 'proxy.config.log.rolling_enabled': 0, 'proxy.config.log.auto_delete_rolled_files': 0, }) + return ts, ts_name - self.diags_log = self.ts.Disk.diags_log.AbsPath + def _configure_server(self): + server = Test.MakeOriginServer(self._next_server_name()) - # Add content handles for the rotated logs. - self.rotated_diags_log = self.diags_log + "_old" - self.ts.Disk.File(self.rotated_diags_log, id="diags_log_old") + for path in ['/first', '/second', '/third']: + request_header = { + 'headers': f'GET {path} HTTP/1.1\r\nHost: does.not.matter\r\n\r\n', + 'timestamp': '1469733493.993', + 'body': '' + } + response_header = { + 'headers': 'HTTP/1.1 200 OK\r\n' + 'Connection: close\r\n' + 'Cache-control: max-age=85000\r\n\r\n', + 'timestamp': '1469733493.993', + 'body': 'xxx' + } + server.addResponse('sessionlog.json', request_header, response_header) + + return server - self.log_dir = os.path.dirname(self.diags_log) + def add_system_log_test(self): + tr = Test.AddTestRun('Verify system logs can be rotated') + ts, ts_name = self._configure_traffic_server(tr) - self.ts.Disk.remap_config.AddLine( - 'map http://127.0.0.1:{0} http://127.0.0.1:{1}'.format(self.ts.Variables.port, self.server.Variables.Port)) - self.ts.Disk.logging_yaml.AddLine( + rotated_diags_log = f'{ts.Disk.diags_log.AbsPath}_old' + ts.Disk.File(rotated_diags_log, id='diags_log_old') + + tr.Processes.Default.Command = self._make_script_command( + ROTATE_DIAGS_SCRIPT, sys.executable, f'./{TS_PID_SCRIPT}', ts_name, ts.Disk.diags_log.AbsPath, rotated_diags_log) + tr.Processes.Default.ReturnCode = 0 + tr.Processes.Default.StartBefore(ts) + + ts.Disk.diags_log.Content += Testers.ExcludesExpression( + 'traffic server running', 'The new diags.log should not reference the running traffic server') + ts.Disk.diags_log.Content += Testers.ContainsExpression( + 'Reseated diags.log', 'The new diags.log should indicate the newly opened diags.log') + ts.Disk.diags_log_old.Content += Testers.ContainsExpression( + 'traffic server running', 'The rotated diags.log should keep the original startup message') + + def add_configured_log_test(self): + tr = Test.AddTestRun('Verify yaml.log logs can be rotated') + ts, ts_name = self._configure_traffic_server(tr) + server = self._configure_server() + + ts.Disk.remap_config.AddLine(f'map http://127.0.0.1:{ts.Variables.port} http://127.0.0.1:{server.Variables.Port}') + ts.Disk.logging_yaml.AddLine( ''' logging: formats: @@ -71,155 +122,43 @@ def __configure_traffic_server(self): - filename: test_rotation format: has_path ''') - self.configured_log = os.path.join(self.log_dir, "test_rotation.log") - self.ts.Disk.File(self.configured_log, id="configured_log") - - self.rotated_configured_log = self.configured_log + "_old" - self.ts.Disk.File(self.rotated_configured_log, id="configured_log_old") - self.ts.StartBefore(self.server) - return self.ts - - def __configure_server(self): - if Sigusr2Test.__server: - return Sigusr2Test.__server - server = Test.MakeOriginServer("server") - Sigusr2Test.__server = server - for path in ['/first', '/second', '/third']: - request_header = { - "headers": "GET {} HTTP/1.1\r\n" - "Host: does.not.matter\r\n\r\n".format(path), - "timestamp": "1469733493.993", - "body": "" - } - response_header = { - "headers": "HTTP/1.1 200 OK\r\n" - "Connection: close\r\n" - "Cache-control: max-age=85000\r\n\r\n", - "timestamp": "1469733493.993", - "body": "xxx" - } - server.addResponse("sessionlog.json", request_header, response_header) - return server - - def get_sigusr2_signal_command(self): - """ - Return the command that will send a USR2 signal to the traffic server - process. - """ - return (f"{sys.executable} {TS_PID_SCRIPT} " - f"--signal SIGUSR2 {self._ts_name}") - - -Test.Summary = ''' -Verify support of external log rotation via SIGUSR2. -''' -Test.Setup.CopyAs(TS_PID_SCRIPT, Test.RunDirectory) + configured_log = os.path.join(ts.Variables.LOGDIR, 'test_rotation.log') + ts.Disk.File(configured_log, id='configured_log') -# -# Test 1: Verify SIGUSR2 behavior for system logs. -# -tr1 = Test.AddTestRun("Verify system logs can be rotated") + rotated_configured_log = f'{configured_log}_old' + ts.Disk.File(rotated_configured_log, id='configured_log_old') -# Configure Server. -diags_test = Sigusr2Test() + ts.StartBefore(server) + tr.Processes.Default.Command = self._make_script_command( + ROTATE_CUSTOM_LOG_SCRIPT, sys.executable, f'./{TS_PID_SCRIPT}', ts_name, ts.Variables.port, configured_log, + rotated_configured_log) + tr.Processes.Default.ReturnCode = 0 + tr.Processes.Default.StartBefore(ts) -# Configure our rotation processes. -rotate_diags_log = tr1.Processes.Process("rotate_diags_log", "mv {} {}".format(diags_test.diags_log, diags_test.rotated_diags_log)) + ts.Disk.configured_log.Content += Testers.ExcludesExpression( + '/first', 'The new test_rotation.log should not have the first GET retrieval in it.') + ts.Disk.configured_log.Content += Testers.ExcludesExpression( + '/second', 'The new test_rotation.log should not have the second GET retrieval in it.') + ts.Disk.configured_log.Content += Testers.ContainsExpression( + '/third', 'The new test_rotation.log should have the third GET retrieval in it.') -# Configure the signaling of SIGUSR2 to traffic_server. -tr1.Processes.Default.Command = diags_test.get_sigusr2_signal_command() -tr1.Processes.Default.Return = 0 -tr1.Processes.Default.Ready = When.FileExists(diags_test.diags_log) + ts.Disk.configured_log_old.Content += Testers.ContainsExpression( + '/first', 'test_rotation.log_old should have the first GET retrieval in it.') + ts.Disk.configured_log_old.Content += Testers.ContainsExpression( + '/second', 'test_rotation.log_old should have the second GET retrieval in it.') + ts.Disk.configured_log_old.Content += Testers.ExcludesExpression( + '/third', 'test_rotation.log_old should not have the third GET retrieval in it.') -# Configure process order. -tr1.Processes.Default.StartBefore(rotate_diags_log) -rotate_diags_log.StartBefore(diags_test.ts) -tr1.StillRunningAfter = diags_test.ts -tr1.StillRunningAfter = diags_test.server -# diags.log should have been rotated. The old one had the reference to traffic -# server running, this new one shouldn't. But it should indicate that the new -# diags.log was opened. -diags_test.ts.Disk.diags_log.Content += Testers.ExcludesExpression( - "traffic server running", "The new diags.log should not reference the running traffic server") +Test.Summary = ''' +Verify support of external log rotation via SIGUSR2. +''' -diags_test.ts.Disk.diags_log.Content += Testers.ContainsExpression( - "Reseated diags.log", "The new diags.log should indicate the newly opened diags.log") +Test.Setup.Copy(TS_PID_SCRIPT) +Test.Setup.Copy(ROTATE_DIAGS_SCRIPT) +Test.Setup.Copy(ROTATE_CUSTOM_LOG_SCRIPT) -# -# Test 2: Verify SIGUSR2 isn't needed for rotated configured logs. -# -tr2 = Test.AddTestRun("Verify yaml.log logs can be rotated") -configured_test = Sigusr2Test() - -first_curl = tr2.Processes.Process( - "first_curl", 'curl "http://127.0.0.1:{0}/first" --verbose'.format(configured_test.ts.Variables.port)) -# Note that for each of these processes, aside from the final Default one, they -# are all treated like long-running servers to AuTest. Thus the long sleeps -# only allow us to wait until the logs get populated with the desired content, -# the test will not wait the entire time for them to complete. -first_curl_ready = tr2.Processes.Process("first_curl_ready", 'sleep 30') -# In the autest environment, it can take more than 10 seconds for the log file to be created. -first_curl_ready.StartupTimeout = 30 -first_curl_ready.Ready = When.FileContains(configured_test.configured_log, "/first") - -rotate_log = tr2.Processes.Process( - "rotate_log_file", "mv {} {}".format(configured_test.configured_log, configured_test.rotated_configured_log)) - -second_curl = tr2.Processes.Process( - "second_curl", 'curl "http://127.0.0.1:{0}/second" --verbose'.format(configured_test.ts.Variables.port)) - -second_curl_ready = tr2.Processes.Process("second_curl_ready", 'sleep 30') -# In the autest environment, it can take more than 10 seconds for the log file to be created. -second_curl_ready.StartupTimeout = 30 -second_curl_ready.Ready = When.FileContains(configured_test.rotated_configured_log, "/second") - -send_pkill = tr2.Processes.Process("Send_SIGUSR2", configured_test.get_sigusr2_signal_command()) -send_pkill_ready = tr2.Processes.Process("send_pkill_ready", 'sleep 30') -send_pkill_ready.StartupTimeout = 30 -send_pkill_ready.Ready = When.FileExists(configured_test.configured_log) - -third_curl = tr2.Processes.Process( - "third_curl", 'curl "http://127.0.0.1:{0}/third" --verbose'.format(configured_test.ts.Variables.port)) -third_curl_ready = tr2.Processes.Process("third_curl_ready", 'sleep 30') -# In the autest environment, it can take more than 10 seconds for the log file to be created. -third_curl_ready.StartupTimeout = 30 -third_curl_ready.Ready = When.FileContains(configured_test.configured_log, "/third") - -tr2.Processes.Default.Command = "echo waiting for test processes to be done" -tr2.Processes.Default.Return = 0 - -# Configure process order: -# 1. curl /first. The entry should be logged to current log which will be _old. -# 2. mv the log to _old. -# 3. curl /second. The entry should end up in _old log. -# 4. Send a SIGUSR2 to traffic_server. The log should be recreated. -# 5. curl /third. The entry should end up in the new, non-old, log file. -# -tr2.Processes.Default.StartBefore(third_curl_ready) -third_curl_ready.StartBefore(third_curl) -third_curl.StartBefore(send_pkill_ready) -send_pkill_ready.StartBefore(send_pkill) -send_pkill.StartBefore(second_curl_ready) -second_curl_ready.StartBefore(second_curl) -second_curl.StartBefore(rotate_log) -rotate_log.StartBefore(first_curl_ready) -first_curl_ready.StartBefore(first_curl) -first_curl.StartBefore(configured_test.ts) -tr2.StillRunningAfter = configured_test.ts - -# Verify that the logs are in the correct files. -configured_test.ts.Disk.configured_log.Content += Testers.ExcludesExpression( - "/first", "The new test_rotation.log should not have the first GET retrieval in it.") -configured_test.ts.Disk.configured_log.Content += Testers.ExcludesExpression( - "/second", "The new test_rotation.log should not have the second GET retrieval in it.") -configured_test.ts.Disk.configured_log.Content += Testers.ContainsExpression( - "/third", "The new test_rotation.log should have the third GET retrieval in it.") - -configured_test.ts.Disk.configured_log_old.Content += Testers.ContainsExpression( - "/first", "test_rotation.log_old should have the first GET retrieval in it.") -configured_test.ts.Disk.configured_log_old.Content += Testers.ContainsExpression( - "/second", "test_rotation.log_old should have the second GET retrieval in it.") -configured_test.ts.Disk.configured_log_old.Content += Testers.ExcludesExpression( - "/third", "test_rotation.log_old should not have the third GET retrieval in it.") +sigusr2_test = Sigusr2Test() +sigusr2_test.add_system_log_test() +sigusr2_test.add_configured_log_test() diff --git a/tests/gold_tests/logging/sigusr2_rotate_custom_log.sh b/tests/gold_tests/logging/sigusr2_rotate_custom_log.sh new file mode 100644 index 00000000000..80b915f998b --- /dev/null +++ b/tests/gold_tests/logging/sigusr2_rotate_custom_log.sh @@ -0,0 +1,101 @@ +#!/usr/bin/env bash +# +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +set -eu + +if [ "$#" -ne 6 ]; then + echo "Usage: $0 " >&2 + exit 2 +fi + +python_bin="$1" +handler="$2" +ts_name="$3" +ats_port="$4" +configured_log="$5" +rotated_configured_log="$6" +base_url="http://127.0.0.1:${ats_port}" + +wait_for_file() { + path="$1" + tries="$2" + attempt=0 + + while [ "$attempt" -lt "$tries" ]; do + if [ -f "$path" ]; then + return 0 + fi + sleep 1 + attempt=$((attempt + 1)) + done + + echo "Timed out waiting for file: $path" >&2 + return 1 +} + +wait_for_contains() { + path="$1" + needle="$2" + tries="$3" + attempt=0 + + while [ "$attempt" -lt "$tries" ]; do + if [ -f "$path" ] && grep -F "$needle" "$path" >/dev/null 2>&1; then + return 0 + fi + sleep 1 + attempt=$((attempt + 1)) + done + + echo "Timed out waiting for '$needle' in $path" >&2 + return 1 +} + +request_path() { + path="$1" + attempt=0 + + while [ "$attempt" -lt 60 ]; do + if curl --fail --silent --show-error --output /dev/null --max-time 5 "${base_url}${path}"; then + return 0 + fi + sleep 1 + attempt=$((attempt + 1)) + done + + echo "Timed out requesting ${base_url}${path}" >&2 + return 1 +} + +rm -f "$configured_log" "$rotated_configured_log" + +request_path "/first" +wait_for_contains "$configured_log" "/first" 60 + +mv "$configured_log" "$rotated_configured_log" + +request_path "/second" +wait_for_contains "$rotated_configured_log" "/second" 60 + +# Send the SIGUSR2 signal to the handler to trigger ATS to rotate the log. +"$python_bin" "$handler" --signal SIGUSR2 "$ts_name" + +wait_for_file "$configured_log" 60 + +request_path "/third" +wait_for_contains "$configured_log" "/third" 60 diff --git a/tests/gold_tests/logging/sigusr2_rotate_diags.sh b/tests/gold_tests/logging/sigusr2_rotate_diags.sh new file mode 100644 index 00000000000..b45bf04ed79 --- /dev/null +++ b/tests/gold_tests/logging/sigusr2_rotate_diags.sh @@ -0,0 +1,79 @@ +#!/usr/bin/env bash +# +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +set -eu + +if [ "$#" -ne 5 ]; then + echo "Usage: $0 " >&2 + exit 2 +fi + +python_bin="$1" +handler="$2" +ts_name="$3" +diags_log="$4" +rotated_diags_log="$5" + +wait_for_file() { + path="$1" + tries="$2" + attempt=0 + + while [ "$attempt" -lt "$tries" ]; do + if [ -f "$path" ]; then + return 0 + fi + sleep 1 + attempt=$((attempt + 1)) + done + + echo "Timed out waiting for file: $path" >&2 + return 1 +} + +wait_for_contains() { + path="$1" + needle="$2" + tries="$3" + attempt=0 + + while [ "$attempt" -lt "$tries" ]; do + if [ -f "$path" ] && grep -F "$needle" "$path" >/dev/null 2>&1; then + return 0 + fi + sleep 1 + attempt=$((attempt + 1)) + done + + echo "Timed out waiting for '$needle' in $path" >&2 + return 1 +} + +rm -f "$rotated_diags_log" + +wait_for_file "$diags_log" 60 +wait_for_contains "$diags_log" "traffic server running" 60 + +mv "$diags_log" "$rotated_diags_log" + +# Send the SIGUSR2 signal to the handler to trigger ATS to rotate the log. +"$python_bin" "$handler" --signal SIGUSR2 "$ts_name" + +wait_for_file "$diags_log" 60 +wait_for_contains "$diags_log" "Reseated diags.log" 60 +wait_for_contains "$rotated_diags_log" "traffic server running" 60