diff --git a/component-tests/test_logging.py b/component-tests/test_logging.py index 0fb550da..3a025682 100644 --- a/component-tests/test_logging.py +++ b/component-tests/test_logging.py @@ -1,24 +1,79 @@ #!/usr/bin/env python import json import os -from util import start_cloudflared, wait_tunnel_ready, send_requests, LOGGER +import subprocess + +from util import start_cloudflared, wait_tunnel_ready, send_requests + +# Rolling logger rotate log files after 1 MB +rotate_after_size = 1000 * 1000 +default_log_file = "cloudflared.log" +expect_message = "Starting tunnel" + + +def assert_log_to_terminal(cloudflared): + stderr = cloudflared.stderr.read(200) + # cloudflared logs the following when it first starts + # 2021-03-10T12:30:39Z INF Starting tunnel tunnelID= + assert expect_message.encode() in stderr, f"{stderr} doesn't contain {expect_message}" + + +def assert_log_in_file(file): + with open(file, "r") as f: + log = f.read(200) + # cloudflared logs the following when it first starts + # {"level":"info","tunnelID":"","time":"2021-03-10T12:21:13Z","message":"Starting tunnel"} + assert expect_message in log, f"{log} doesn't contain {expect_message}" + + +def assert_json_log(file): + def assert_in_json(j, key): + assert key in j, f"{key} is not in j" + + with open(file, "r") as f: + line = f.readline() + json_log = json.loads(line) + assert_in_json(json_log, "level") + assert_in_json(json_log, "time") + assert_in_json(json_log, "message") + + +def assert_log_to_dir(config, log_dir): + max_batches = 3 + batch_requests = 1000 + for _ in range(max_batches): + send_requests(config.get_url(), + batch_requests, require_ok=False) + files = os.listdir(log_dir) + if len(files) == 2: + current_log_file_index = files.index(default_log_file) + current_file = log_dir / files[current_log_file_index] + stats = os.stat(current_file) + assert stats.st_size > 0 + assert_json_log(current_file) + + # One file is the current log file, the other is the rotated log file + rotated_log_file_index = 0 if current_log_file_index == 1 else 1 + rotated_file = log_dir / files[rotated_log_file_index] + stats = os.stat(rotated_file) + assert stats.st_size > rotate_after_size + assert_log_in_file(rotated_file) + assert_json_log(current_file) + return + + raise Exception( + f"Log file isn't rotated after sending {max_batches * batch_requests} requests") class TestLogging: - # TODO: Test logging when running as a service https://jira.cfops.it/browse/TUN-4082 - # Rolling logger rotate log files after 1 MB - rotate_after_size = 1000 * 1000 - default_log_file = "cloudflared.log" - expect_message = "Starting tunnel" - def test_logging_to_terminal(self, tmp_path, component_tests_config): config = component_tests_config() with start_cloudflared(tmp_path, config, new_process=True) as cloudflared: wait_tunnel_ready(tunnel_url=config.get_url()) - self.assert_log_to_terminal(cloudflared) + assert_log_to_terminal(cloudflared) def test_logging_to_file(self, tmp_path, component_tests_config): - log_file = tmp_path / self.default_log_file + log_file = tmp_path / default_log_file extra_config = { # Convert from pathlib.Path to str "logfile": str(log_file), @@ -26,8 +81,8 @@ class TestLogging: config = component_tests_config(extra_config) with start_cloudflared(tmp_path, config, new_process=True, capture_output=False): wait_tunnel_ready(tunnel_url=config.get_url()) - self.assert_log_in_file(log_file) - self.assert_json_log(log_file) + assert_log_in_file(log_file) + assert_json_log(log_file) def test_logging_to_dir(self, tmp_path, component_tests_config): log_dir = tmp_path / "logs" @@ -39,55 +94,4 @@ class TestLogging: config = component_tests_config(extra_config) with start_cloudflared(tmp_path, config, new_process=True, capture_output=False): wait_tunnel_ready(tunnel_url=config.get_url()) - self.assert_log_to_dir(config, log_dir) - - def assert_log_to_terminal(self, cloudflared): - stderr = cloudflared.stderr.read(200) - # cloudflared logs the following when it first starts - # 2021-03-10T12:30:39Z INF Starting tunnel tunnelID= - assert self.expect_message.encode( - ) in stderr, f"{stderr} doesn't contain {self.expect_message}" - - def assert_log_in_file(self, file, expect_message=""): - with open(file, "r") as f: - log = f.read(200) - # cloudflared logs the following when it first starts - # {"level":"info","tunnelID":"","time":"2021-03-10T12:21:13Z","message":"Starting tunnel"} - assert self.expect_message in log, f"{log} doesn't contain {self.expect_message}" - - def assert_json_log(self, file): - with open(file, "r") as f: - line = f.readline() - json_log = json.loads(line) - self.assert_in_json(json_log, "level") - self.assert_in_json(json_log, "time") - self.assert_in_json(json_log, "message") - - def assert_in_json(self, j, key): - assert key in j, f"{key} is not in j" - - def assert_log_to_dir(self, config, log_dir): - max_batches = 3 - batch_requests = 1000 - for _ in range(max_batches): - send_requests(config.get_url(), - batch_requests, require_ok=False) - files = os.listdir(log_dir) - if len(files) == 2: - current_log_file_index = files.index(self.default_log_file) - current_file = log_dir / files[current_log_file_index] - stats = os.stat(current_file) - assert stats.st_size > 0 - self.assert_json_log(current_file) - - # One file is the current log file, the other is the rotated log file - rotated_log_file_index = 0 if current_log_file_index == 1 else 1 - rotated_file = log_dir / files[rotated_log_file_index] - stats = os.stat(rotated_file) - assert stats.st_size > self.rotate_after_size - self.assert_log_in_file(rotated_file) - self.assert_json_log(current_file) - return - - raise Exception( - f"Log file isn't rotated after sending {max_batches * batch_requests} requests") + assert_log_to_dir(config, log_dir) diff --git a/component-tests/test_service.py b/component-tests/test_service.py index 7795a570..c4b27dca 100644 --- a/component-tests/test_service.py +++ b/component-tests/test_service.py @@ -1,12 +1,14 @@ #!/usr/bin/env python -from contextlib import contextmanager import os -from pathlib import Path import platform -import pytest import subprocess +from contextlib import contextmanager +from pathlib import Path -from util import start_cloudflared, cloudflared_cmd, wait_tunnel_ready, LOGGER +import pytest + +import test_logging +from util import start_cloudflared, wait_tunnel_ready def select_platform(plat): @@ -22,34 +24,94 @@ def default_config_file(): return os.path.join(default_config_dir(), "config.yml") -class TestServiceMode(): +class TestServiceMode: @select_platform("Darwin") @pytest.mark.skipif(os.path.exists(default_config_file()), reason=f"There is already a config file in default path") - def test_launchd_service(self, component_tests_config): - # On Darwin cloudflared service defaults to run classic tunnel command + def test_launchd_service_log_to_file(self, tmp_path, component_tests_config): + log_file = tmp_path / test_logging.default_log_file additional_config = { + # On Darwin cloudflared service defaults to run classic tunnel command "hello-world": True, + "logfile": str(log_file), } - config = component_tests_config( - additional_config=additional_config, named_tunnel=False) + config = component_tests_config(additional_config=additional_config, named_tunnel=False) + + def assert_log_file(): + test_logging.assert_log_in_file(log_file) + test_logging.assert_json_log(log_file) + + self.launchd_service_scenario(config, assert_log_file) + + @select_platform("Darwin") + @pytest.mark.skipif(os.path.exists(default_config_file()), reason=f"There is already a config file in default path") + def test_launchd_service_rotating_log(self, tmp_path, component_tests_config): + log_dir = tmp_path / "logs" + additional_config = { + # On Darwin cloudflared service defaults to run classic tunnel command + "hello-world": True, + "loglevel": "debug", + "log-directory": str(log_dir), + } + config = component_tests_config(additional_config=additional_config, named_tunnel=False) + + def assert_rotating_log(): + test_logging.assert_log_to_dir(config, log_dir) + + self.launchd_service_scenario(config, assert_rotating_log) + + def launchd_service_scenario(self, config, extra_assertions): with self.run_service(Path(default_config_dir()), config): self.launchctl_cmd("list") self.launchctl_cmd("start") wait_tunnel_ready(tunnel_url=config.get_url()) + extra_assertions() self.launchctl_cmd("stop") os.remove(default_config_file()) self.launchctl_cmd("list", success=False) @select_platform("Linux") - @pytest.mark.skipif(os.path.exists("/etc/cloudflared/config.yml"), reason=f"There is already a config file in default path") - def test_sysv_service(self, tmp_path, component_tests_config): - config = component_tests_config() + @pytest.mark.skipif(os.path.exists("/etc/cloudflared/config.yml"), + reason=f"There is already a config file in default path") + def test_sysv_service_log_to_file(self, tmp_path, component_tests_config): + log_file = tmp_path / test_logging.default_log_file + additional_config = { + "logfile": str(log_file), + } + config = component_tests_config(additional_config=additional_config) + + def assert_log_file(): + test_logging.assert_log_in_file(log_file) + test_logging.assert_json_log(log_file) + + self.sysv_service_scenario(config, tmp_path, assert_log_file) + + @select_platform("Linux") + @pytest.mark.skipif(os.path.exists("/etc/cloudflared/config.yml"), + reason=f"There is already a config file in default path") + def test_sysv_service_rotating_log(self, tmp_path, component_tests_config): + log_dir = tmp_path / "logs" + additional_config = { + "loglevel": "debug", + "log-directory": str(log_dir), + } + config = component_tests_config(additional_config=additional_config) + + def assert_rotating_log(): + # We need the folder to have executable permissions for the "stat" command in the assertions to work. + subprocess.check_call(['sudo', 'chmod', 'o+x', log_dir]) + test_logging.assert_log_to_dir(config, log_dir) + + self.sysv_service_scenario(config, tmp_path, assert_rotating_log) + + def sysv_service_scenario(self, config, tmp_path, extra_assertions): with self.run_service(tmp_path, config, root=True): self.sysv_cmd("start") self.sysv_cmd("status") wait_tunnel_ready(tunnel_url=config.get_url()) + extra_assertions() self.sysv_cmd("stop") + # Service install copies config file to /etc/cloudflared/config.yml subprocess.run(["sudo", "rm", "/etc/cloudflared/config.yml"]) self.sysv_cmd("status", success=False)