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