TUN-4082: Test logging when running as a service

Author: nmldiegues

component-tests/test_logging.py

@@ -1,33 +1,88 @@
 #!/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
 
-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"
+# 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=<tunnel ID>
+    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":"<tunnel ID>","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:
     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),
         }
         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 @@ def test_logging_to_dir(self, tmp_path, component_tests_config):
         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=<tunnel ID>
-        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":"<tunnel ID>","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)

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
+
+import pytest
 
-from util import start_cloudflared, cloudflared_cmd, wait_tunnel_ready, LOGGER
+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_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)
+
+        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(self, component_tests_config):
-        # On Darwin cloudflared service defaults to run classic tunnel command
+    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)
+        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)