TUN-4049: Add component tests to assert logging behavior when running from terminal

component-tests/README.md

@@ -12,8 +12,25 @@ tunnel: "3d539f97-cd3a-4d8e-c33b-65e9099c7a8d"
 credentials_file: "/Users/tunnel/.cloudflared/3d539f97-cd3a-4d8e-c33b-65e9099c7a8d.json"
 classic_hostname: "classic-tunnel-component-tests.example.com"
 origincert: "/Users/tunnel/.cloudflared/cert.pem"
+ingress:
+- hostname: named-tunnel-component-tests.example.com
+  service: http_status:200
+- service: http_status:404
 ```
 
+3. Route hostname to the tunnel. For the example config above, we can do that via
+```
+   cloudflared tunnel route dns 3d539f97-cd3a-4d8e-c33b-65e9099c7a8d named-tunnel-component-tests.example.com
+```
+
+4. Turn on linter
+If you are using Visual Studio, follow https://code.visualstudio.com/docs/python/linting to turn on linter.
+
+5. Turn on formatter
+If you are using Visual Studio, follow https://code.visualstudio.com/docs/python/editing#_formatting
+to turn on formatter and https://marketplace.visualstudio.com/items?itemName=cbrevik.toggle-format-on-save
+to turn on format on save.
+
 # How to run
 Specify path to config file via env var `COMPONENT_TESTS_CONFIG`. This is required.
 ## All tests

component-tests/config.py

@@ -4,11 +4,15 @@ import copy
 import os
 import yaml
 
-from dataclasses import dataclass
+from dataclasses import dataclass, InitVar
 
 from constants import METRICS_PORT
 
+from util import LOGGER
+
 # frozen=True raises exception when assigning to fields. This emulates immutability
+
+
 @dataclass(frozen=True)
 class TunnelBaseConfig:
     no_autoupdate: bool = True
@@ -27,20 +31,41 @@ class NamedTunnelBaseConfig(TunnelBaseConfig):
     # so we have to use default values here and check if they are set in __post_init__
     tunnel: str = None
     credentials_file: str = None
+    ingress: list = None
 
     def __post_init__(self):
         if self.tunnel is None:
             raise TypeError("Field tunnel is not set")
         if self.credentials_file is None:
             raise TypeError("Field credentials_file is not set")
+        if self.ingress is None:
+            raise TypeError("Field ingress is not set")
 
     def merge_config(self, additional):
         config = super(NamedTunnelBaseConfig, self).merge_config(additional)
         config['tunnel'] = self.tunnel
         config['credentials-file'] = self.credentials_file
+        # In some cases we want to override default ingress, such as in config tests
+        if 'ingress' not in config:
+            config['ingress'] = self.ingress
         return config
 
 
+@dataclass(frozen=True)
+class NamedTunnelConfig(NamedTunnelBaseConfig):
+    full_config: dict = None
+    additional_config: InitVar[dict] = {}
+
+    def __post_init__(self, additional_config):
+        # Cannot call set self.full_config because the class is frozen, instead, we can use __setattr__
+        # https://docs.python.org/3/library/dataclasses.html#frozen-instances
+        object.__setattr__(self, 'full_config',
+                           self.merge_config(additional_config))
+
+    def get_url(self):
+        return "https://" + self.ingress[0]['hostname']
+
+
 @dataclass(frozen=True)
 class ClassicTunnelBaseConfig(TunnelBaseConfig):
     hostname: str = None
@@ -54,21 +79,37 @@ class ClassicTunnelBaseConfig(TunnelBaseConfig):
 
     def merge_config(self, additional):
         config = super(ClassicTunnelBaseConfig, self).merge_config(additional)
-        config['hostnamel'] = self.hostname
+        config['hostname'] = self.hostname
         config['origincert'] = self.origincert
         return config
 
 
+@dataclass(frozen=True)
+class ClassicTunnelConfig(ClassicTunnelBaseConfig):
+    full_config: dict = None
+    additional_config: InitVar[dict] = {}
+
+    def __post_init__(self, additional_config):
+        # Cannot call set self.full_config because the class is frozen, instead, we can use __setattr__
+        # https://docs.python.org/3/library/dataclasses.html#frozen-instances
+        object.__setattr__(self, 'full_config',
+                           self.merge_config(additional_config))
+
+    def get_url(self):
+        return "https://" + self.hostname
+
+
 @dataclass
 class ComponentTestConfig:
     cloudflared_binary: str
-    named_tunnel_config: dict
-    classic_tunnel_config: dict
+    named_tunnel_config: NamedTunnelConfig
+    classic_tunnel_config: ClassicTunnelConfig
 
 
 def build_config_from_env():
     config_path = get_env("COMPONENT_TESTS_CONFIG")
-    config_content = base64.b64decode(get_env("COMPONENT_TESTS_CONFIG_CONTENT")).decode('utf-8')
+    config_content = base64.b64decode(
+        get_env("COMPONENT_TESTS_CONFIG_CONTENT")).decode('utf-8')
     config_yaml = yaml.safe_load(config_content)
 
     credentials_file = get_env("COMPONENT_TESTS_CREDENTIALS_FILE")

component-tests/conftest.py

@@ -2,23 +2,34 @@ import os
 import pytest
 import yaml
 
-from config import ComponentTestConfig, NamedTunnelBaseConfig, ClassicTunnelBaseConfig
+from time import sleep
+
+from config import ComponentTestConfig, NamedTunnelConfig, ClassicTunnelConfig
+from constants import BACKOFF_SECS
 from util import LOGGER
 
+
 @pytest.fixture(scope="session")
 def component_tests_config():
     config_file = os.getenv("COMPONENT_TESTS_CONFIG")
     if config_file is None:
-        raise Exception("Need to provide path to config file in COMPONENT_TESTS_CONFIG")
+        raise Exception(
+            "Need to provide path to config file in COMPONENT_TESTS_CONFIG")
     with open(config_file, 'r') as stream:
         config = yaml.safe_load(stream)
         LOGGER.info(f"component tests base config {config}")
-        base_named_tunnel_config = NamedTunnelBaseConfig(tunnel=config['tunnel'], credentials_file=config['credentials_file'])
-        base_classic_tunnel_config = ClassicTunnelBaseConfig(hostname=config['classic_hostname'], origincert=config['origincert'])
 
         def _component_tests_config(extra_named_tunnel_config={}, extra_classic_tunnel_config={}):
-            named_tunnel_config = base_named_tunnel_config.merge_config(extra_named_tunnel_config)
-            classic_tunnel_config = base_classic_tunnel_config.merge_config(extra_classic_tunnel_config)
+            named_tunnel_config = NamedTunnelConfig(additional_config=extra_named_tunnel_config,
+                                                    tunnel=config['tunnel'], credentials_file=config['credentials_file'],  ingress=config['ingress'])
+            classic_tunnel_config = ClassicTunnelConfig(
+                additional_config=extra_classic_tunnel_config, hostname=config['classic_hostname'], origincert=config['origincert'])
             return ComponentTestConfig(config['cloudflared_binary'], named_tunnel_config, classic_tunnel_config)
 
         return _component_tests_config
+
+
+# This fixture is automatically called before each tests to make sure the previous cloudflared has been shutdown
+@pytest.fixture(autouse=True)
+def wait_previous_cloudflared():
+    sleep(BACKOFF_SECS)

component-tests/constants.py

@@ -1 +1,3 @@
 METRICS_PORT = 51000
+MAX_RETRIES = 3
+BACKOFF_SECS = 5

component-tests/requirements.txt

@@ -1,2 +1,4 @@
 pytest==6.2.2
 pyyaml==5.4.1
+requests==2.25.1
+retrying==1.3.3

component-tests/test_config.py

@@ -1,6 +1,7 @@
 #!/usr/bin/env python
 from util import start_cloudflared
 
+
 class TestConfig:
     # tmp_path is a fixture provides a temporary directory unique to the test invocation
     def test_validate_ingress_rules(self, tmp_path, component_tests_config):
@@ -32,23 +33,25 @@ class TestConfig:
         }
         component_tests_config = component_tests_config(extra_config)
         validate_args = ["ingress", "validate"]
-        pre_args = ["tunnel"]
-        validate = start_cloudflared(tmp_path, component_tests_config, validate_args, pre_args)
-        assert validate.returncode == 0, "failed to validate ingress" + validate.stderr.decode("utf-8")
-
-        self.match_rule(tmp_path, component_tests_config, "http://example.com/index.html", 1)
-        self.match_rule(tmp_path, component_tests_config, "https://example.com/index.html", 1)
-        self.match_rule(tmp_path, component_tests_config, "https://api.example.com/login", 2)
-        self.match_rule(tmp_path, component_tests_config, "https://wss.example.com", 3)
-        self.match_rule(tmp_path, component_tests_config, "https://ssh.example.com", 4)
-        self.match_rule(tmp_path, component_tests_config, "https://api.example.com", 5)
+        _ = start_cloudflared(tmp_path, component_tests_config, validate_args)
 
+        self.match_rule(tmp_path, component_tests_config,
+                        "http://example.com/index.html", 1)
+        self.match_rule(tmp_path, component_tests_config,
+                        "https://example.com/index.html", 1)
+        self.match_rule(tmp_path, component_tests_config,
+                        "https://api.example.com/login", 2)
+        self.match_rule(tmp_path, component_tests_config,
+                        "https://wss.example.com", 3)
+        self.match_rule(tmp_path, component_tests_config,
+                        "https://ssh.example.com", 4)
+        self.match_rule(tmp_path, component_tests_config,
+                        "https://api.example.com", 5)
 
     # This is used to check that the command tunnel ingress url <url> matches rule number <rule_num>. Note that rule number uses 1-based indexing
+
     def match_rule(self, tmp_path, component_tests_config, url, rule_num):
         args = ["ingress", "rule", url]
-        pre_args = ["tunnel"]
-        match_rule = start_cloudflared(tmp_path, component_tests_config, args, pre_args)
+        match_rule = start_cloudflared(tmp_path, component_tests_config, args)
 
-        assert match_rule.returncode == 0, "failed to check rule" + match_rule.stderr.decode("utf-8")
         assert f"Matched rule #{rule_num}" .encode() in match_rule.stdout

component-tests/test_logging.py

@@ -0,0 +1,92 @@
+#!/usr/bin/env python
+import json
+import os
+from util import start_cloudflared, wait_tunnel_ready, send_requests, LOGGER
+
+
+class TestLogging:
+    # 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()
+            self.assert_log_to_terminal(cloudflared)
+
+    def test_logging_to_file(self, tmp_path, component_tests_config):
+        log_file = tmp_path / self.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()
+            self.assert_log_in_file(log_file)
+            self.assert_json_log(log_file)
+
+    def test_logging_to_dir(self, tmp_path, component_tests_config):
+        log_dir = tmp_path / "logs"
+        extra_config = {
+            "loglevel": "debug",
+            # Convert from pathlib.Path to str
+            "log-directory": str(log_dir),
+        }
+        config = component_tests_config(extra_config)
+        with start_cloudflared(tmp_path, config, new_process=True, capture_output=False):
+            wait_tunnel_ready()
+            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.named_tunnel_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")

component-tests/util.py

@@ -1,10 +1,17 @@
+from contextlib import contextmanager
 import logging
-import os
+import requests
+from retrying import retry
 import subprocess
 import yaml
 
+from time import sleep
+
+from constants import METRICS_PORT, MAX_RETRIES, BACKOFF_SECS
+
 LOGGER = logging.getLogger(__name__)
 
+
 def write_config(path, config):
     config_path = path / "config.yaml"
     with open(config_path, 'w') as outfile:
@@ -12,15 +19,57 @@ def write_config(path, config):
     return config_path
 
 
-def start_cloudflared(path, component_test_config, cfd_args, cfd_pre_args=[], classic=False):
+def start_cloudflared(path, component_test_config, cfd_args=["run"], cfd_pre_args=["tunnel"], new_process=False, classic=False, capture_output=True):
     if classic:
-        config = component_test_config.classic_tunnel_config
+        config = component_test_config.classic_tunnel_config.full_config
     else:
-        config = component_test_config.named_tunnel_config
+        config = component_test_config.named_tunnel_config.full_config
     config_path = write_config(path, config)
     cmd = [component_test_config.cloudflared_binary]
     cmd += cfd_pre_args
     cmd += ["--config", config_path]
     cmd += cfd_args
     LOGGER.info(f"Run cmd {cmd} with config {config}")
-    return subprocess.run(cmd, capture_output=True)
+    if new_process:
+        return run_cloudflared_background(cmd, capture_output)
+    # By setting check=True, it will raise an exception if the process exits with non-zero exit code
+    return subprocess.run(cmd, check=True, capture_output=capture_output)
+
+
+@contextmanager
+def run_cloudflared_background(cmd, capture_output):
+    output = subprocess.PIPE if capture_output else subprocess.DEVNULL
+    try:
+        cfd = subprocess.Popen(cmd, stdout=output, stderr=output)
+        yield cfd
+    finally:
+        cfd.terminate()
+
+
+@retry(stop_max_attempt_number=MAX_RETRIES, wait_fixed=BACKOFF_SECS * 1000)
+def wait_tunnel_ready():
+    url = f'http://localhost:{METRICS_PORT}/ready'
+    send_requests(url, 1)
+
+# In some cases we don't need to check response status, such as when sending batch requests to generate logs
+
+
+def send_requests(url, count, require_ok=True):
+    errors = 0
+    with requests.Session() as s:
+        for _ in range(count):
+            ok = send_request(s, url, require_ok)
+            if not ok:
+                errors += 1
+            sleep(0.01)
+    if errors > 0:
+        LOGGER.warning(
+            f"{errors} out of {count} requests to {url} return non-200 status")
+
+
+@retry(stop_max_attempt_number=MAX_RETRIES, wait_fixed=BACKOFF_SECS * 1000)
+def send_request(session, url, require_ok):
+    resp = session.get(url, timeout=BACKOFF_SECS)
+    if require_ok:
+        assert resp.status_code == 200, f"{url} returned {resp}"
+    return True if resp.status_code == 200 else False