diff --git a/README.md b/README.md index 420159c6b..de481a592 100644 --- a/README.md +++ b/README.md @@ -44,7 +44,7 @@ as root: - Python version till 3.11 is supported, version **3.12 is NOT supported** (we use [asyncore](https://docs.python.org/3.11/library/asyncore.html) that was removed in 3.12) - +- ClickHouse Database 25 (Optional, used for storing logs in the database). See installation [here](https://clickhouse.com/docs/en/install#quick-install) - Host for testing framework: `python3`, `wrk`, `ab`, `nghttp2`, `h2spec`, `curl`, `h2load`, `tls-perf`, `netstat`, `lxc`, `nginx`, `docker.io`, web content directory accessible by nginx, nginx should not be running before the tests start. @@ -84,7 +84,7 @@ You can also create default tests configuration ./run_tests.py -d ``` -There is 4 sections in configuration: `General`, `Client`, `Tempesta`, `Server`. +There is 5 sections in configuration: `General`, `Client`, `Tempesta`, `Server`, `TFW_Logger`. ### Run tests diff --git a/helpers/access_log.py b/helpers/access_log.py index 7c5e2b506..7b6794d0a 100644 --- a/helpers/access_log.py +++ b/helpers/access_log.py @@ -1,8 +1,10 @@ import dataclasses import re import typing +from ipaddress import IPv4Address, IPv6Address -from helpers.dmesg import DmesgFinder +if typing.TYPE_CHECKING: + from helpers.dmesg import DmesgFinder __author__ = "Tempesta Technologies, Inc." __copyright__ = "Copyright (C) 2018-2025 Tempesta Technologies, Inc." @@ -11,27 +13,30 @@ @dataclasses.dataclass class AccessLogLine: - ip: str + address: typing.Union[IPv4Address, IPv6Address] vhost: str - method: str + method: typing.Union[str, int] uri: str - version: str + version: int status: int - response_length: str + response_content_length: int referer: str user_agent: str ja5t: str ja5h: str + timestamp: typing.Optional[int] = None + dropped_events: typing.Optional[int] = None + response_time: typing.Optional[int] = None re_pattern: re.Pattern = re.compile( r"\[tempesta fw\] " - r"(?P\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}) " + r"(?P
\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}) " r"\"(?P[\w.-]+)\" " r"\"(?P[\w]+) " r"(?P.*) " r"HTTP\/(?P[\d.]+)\" " r"(?P\d+) " - r"(?P\d+) " + r"(?P\d+) " r"\"(?P.*)\" " r"\"(?P.*)\" " r"\"ja5t=(?P\w+)\" " @@ -72,7 +77,7 @@ def parse(cls, text: str) -> typing.Optional["AccessLogLine"]: return cls(*res[0]) @classmethod - def from_dmesg(cls, klog: DmesgFinder) -> typing.Optional["AccessLogLine"]: + def from_dmesg(cls, klog: "DmesgFinder") -> typing.Optional["AccessLogLine"]: """ Find the first entry of access log in dmesg """ diff --git a/helpers/clickhouse.py b/helpers/clickhouse.py new file mode 100644 index 000000000..0f95d6633 --- /dev/null +++ b/helpers/clickhouse.py @@ -0,0 +1,154 @@ +"""Simple client for Clickhouse access log storage""" + +import re +import typing + +import clickhouse_connect + +from helpers import dmesg, remote, tf_cfg +from helpers.access_log import AccessLogLine + +__author__ = "Tempesta Technologies, Inc." +__copyright__ = "Copyright (C) 2018-2025 Tempesta Technologies, Inc." +__license__ = "GPL2" + +from helpers.dmesg import amount_one +from helpers.util import wait_until + + +class ClickHouseFinder(dmesg.BaseTempestaLogger): + def __init__(self): + self.raise_error_on_logger_file_missing: bool = True + self.daemon_log: str = tf_cfg.cfg.get("TFW_Logger", "daemon_log") + self.node = remote.tempesta + self.start_time = float(self.node.run_cmd("date +%s.%N")[0]) + self._clickhouse_client = clickhouse_connect.get_client( + host=tf_cfg.cfg.get("TFW_Logger", "clickhouse_host"), + port=int(tf_cfg.cfg.get("TFW_Logger", "clickhouse_port")), + username=tf_cfg.cfg.get("TFW_Logger", "clickhouse_username"), + password=tf_cfg.cfg.get("TFW_Logger", "clickhouse_password"), + database=tf_cfg.cfg.get("TFW_Logger", "clickhouse_database"), + ) + self.__log_data: str = "" + + def update(self) -> None: + """ + Read data of tfw_logger daemon file + """ + stdout, _ = self.node.run_cmd(f"cat {self.daemon_log}") + self.__log_data = stdout.decode() + + def log_findall(self, pattern: str): + return re.findall(pattern, self.__log_data, flags=re.MULTILINE | re.DOTALL) + + def find(self, pattern: str, cond: typing.Callable = amount_one) -> bool: + self.update() + lines = self.log_findall(pattern) + return cond(lines) + + def show(self) -> None: + print(self.__log_data) + + def access_log_clear(self) -> None: + """ + Delete all log records + """ + self._clickhouse_client.command("delete from access_log where true") + + def access_log_records_count(self) -> int: + """ + Count all the log records + """ + res = self._clickhouse_client.query("select count(1) from access_log") + return res.result_rows[0][0] + + def access_log_records_all(self) -> typing.List[AccessLogLine]: + """ + Read all the log records + """ + results = self._clickhouse_client.query( + """ + select * + from access_log + order by timestamp desc + """, + ) + return list( + map( + lambda x: AccessLogLine( + timestamp=x[0], + address=x[1], + method=x[2], + version=x[3], + status=x[4], + response_content_length=x[5], + response_time=x[6], + vhost=x[7], + uri=x[8], + referer=x[9], + user_agent=x[10], + ja5t=x[11], + ja5h=x[12], + dropped_events=x[13], + ), + results.result_rows, + ) + ) + + def access_log_last_message(self) -> typing.Optional[AccessLogLine]: + """ + Read the data of tfw_logger daemon file + """ + records = self.access_log_records_all() + + if not records: + return None + + return records[-1] + + def access_log_table_exists(self) -> bool: + """ + Check if table already created + """ + result = self._clickhouse_client.command("exists table access_log") + return result == 1 + + def tfw_log_file_remove(self) -> None: + """ + Remove tfw logger file + """ + stdout, stderr = self.node.run_cmd(f"rm -f {self.daemon_log}") + assert (stdout, stderr) == (b"", b"") + + def tfw_log_file_exists(self) -> bool: + """ + Check if tfw log file exists + """ + stdout, stderr = self.node.run_cmd(f"ls -la {self.daemon_log} | wc -l") + return (stdout, stderr) == (b"1\n", b"") + + def tfw_logger_signal(self, signal: typing.Literal["STOP", "CONT"]) -> None: + self.node.run_cmd(f"kill -{signal} $(pidof tfw_logger)") + + def tfw_logger_wait_until_ready(self, timeout: int = 5) -> None: + """ + Block thread until tfw_logger starts + """ + + def wait(): + if not self.tfw_log_file_exists(): + return True + + if not self.find("Daemon started\n"): + return True + + return False + + result = wait_until(wait_cond=wait, timeout=timeout, poll_freq=0.1) + + if result or not self.raise_error_on_logger_file_missing: + return + + raise FileNotFoundError( + f'TFW logger daemon log file (path="{self.daemon_log}") was not found' + ) diff --git a/helpers/dmesg.py b/helpers/dmesg.py index bacfdcde8..61b35ae7e 100644 --- a/helpers/dmesg.py +++ b/helpers/dmesg.py @@ -2,7 +2,9 @@ from __future__ import print_function +import abc import re +import typing from contextlib import contextmanager from typing import Callable, List @@ -12,6 +14,8 @@ __copyright__ = "Copyright (C) 2018-2024 Tempesta Technologies, Inc." __license__ = "GPL2" +from .access_log import AccessLogLine + # Collection of conditions for DmesgFinder.find def amount_one(matches: List[str]) -> bool: @@ -34,7 +38,52 @@ def amount_greater_eq(expected: int) -> Callable[[List[str]], bool]: return lambda matches: len(matches) >= expected -class DmesgFinder(object): +class BaseTempestaLogger: + + @abc.abstractmethod + def update(self): + """ + Update logger data + """ + + @abc.abstractmethod + def find(self, pattern: str, cond: typing.Callable = amount_one) -> bool: + """ + Apply the condition to the parsed text with the provided regexp pattern + """ + + @abc.abstractmethod + def log_findall(self, pattern: str): + """ + Find all the text lines fitted with the regexp pattern + """ + + @abc.abstractmethod + def show(self) -> None: + """ + Prints the log data to the stdout + """ + + @abc.abstractmethod + def access_log_records_count(self) -> int: + """ + Count the number of access log records + """ + + @abc.abstractmethod + def access_log_records_all(self) -> typing.List[AccessLogLine]: + """ + Return all access log records + """ + + @abc.abstractmethod + def access_log_last_message(self) -> AccessLogLine: + """ + Return the last access log record + """ + + +class DmesgFinder(BaseTempestaLogger): """dmesg helper class.""" def __init__(self, disable_ratelimit=False): @@ -98,6 +147,23 @@ def wait_cond(): return util.wait_until(wait_cond, timeout=2, poll_freq=0.2) + def access_log_records_all(self) -> typing.List[AccessLogLine]: + if isinstance(self.log, bytes): + return AccessLogLine.parse_all(self.log.decode()) + + return AccessLogLine.parse_all(self.log) + + def access_log_records_count(self) -> int: + return len(self.access_log_records_all()) + + def access_log_last_message(self) -> typing.Optional[AccessLogLine]: + messages = self.access_log_records_all() + + if not messages: + return None + + return messages[-1] + WARN_GENERIC = "Warning: " WARN_SPLIT_ATTACK = "Warning: Paired request missing, HTTP Response Splitting attack?" diff --git a/helpers/tf_cfg.py b/helpers/tf_cfg.py index 2606c3c08..c48bbe792 100644 --- a/helpers/tf_cfg.py +++ b/helpers/tf_cfg.py @@ -83,7 +83,7 @@ def __init__(self, filename=None): self.configure_logger() def __fill_kvs(self): - for section in ["General", "Client", "Tempesta", "Server"]: + for section in ["General", "Client", "Tempesta", "Server", "TFW_Logger"]: cfg = self.config[section] for key in cfg.keys(): id = "_".join([section.lower(), key]) @@ -152,6 +152,14 @@ def defaults(self): "website_user": "", "website_password": "", }, + "TFW_Logger": { + "clickhouse_host": "localhost", + "clickhouse_port": "8123", + "clickhouse_username": "default", + "clickhouse_password": "", + "clickhouse_database": "default", + "daemon_log": "/tmp/tfw_logger.log", + }, } ) diff --git a/helpers/util.py b/helpers/util.py index 78a012f79..c78443791 100644 --- a/helpers/util.py +++ b/helpers/util.py @@ -3,6 +3,7 @@ """ import time +import typing from string import Template from . import remote, tf_cfg @@ -12,7 +13,12 @@ __license__ = "GPL2" -def wait_until(wait_cond, timeout=5, poll_freq=0.01, abort_cond=lambda: False): +def wait_until( + wait_cond: typing.Callable, + timeout=5, + poll_freq=0.01, + abort_cond: typing.Callable = lambda: False, +) -> typing.Optional[bool]: t0 = time.time() while wait_cond(): diff --git a/requirements.txt b/requirements.txt index 2fd686b6a..f2ad6a221 100644 --- a/requirements.txt +++ b/requirements.txt @@ -19,7 +19,7 @@ isort==5.12.0 black==23.1.0 inquirer parameterized - +clickhouse-connect==0.8.11 psutil~=5.9.8 # install mhddos requirements diff --git a/setup.sh b/setup.sh index 343770548..2709bf0d0 100755 --- a/setup.sh +++ b/setup.sh @@ -87,3 +87,15 @@ lxc stop tempesta-site-stage # docker cd "${CURRENT_DIR}" ./tools/docker/install-docker.sh + +# ClickHouse +mkdir /tmp/clickhouse-install & cd /tmp/clickhouse-install +apt install apt-transport-https ca-certificates gnupg -y +curl -fsSL 'https://packages.clickhouse.com/rpm/lts/repodata/repomd.xml.key' | sudo gpg --dearmor -o /usr/share/keyrings/clickhouse-keyring.gpg +ARCH=$(dpkg --print-architecture) +echo "deb [signed-by=/usr/share/keyrings/clickhouse-keyring.gpg arch=${ARCH}] https://packages.clickhouse.com/deb stable main" | sudo tee /etc/apt/sources.list.d/clickhouse.list +apt update +apt install clickhouse-server clickhouse-client -y +rm -f /etc/clickhouse-server/users.d/default-password.xml +systemctl enable clickhouse-server.service +systemctl start clickhouse-server.service diff --git a/t_access_log/test_access_log.py b/t_access_log/test_access_log.py index 116d06d7e..7491914f0 100644 --- a/t_access_log/test_access_log.py +++ b/t_access_log/test_access_log.py @@ -171,7 +171,7 @@ def test_uri_truncate(self): self.assertEqual(msg.uri[-4:], "1...", "URI does not looks truncated") self.assertEqual(msg.user_agent, "user-agent", "Wrong user-agent") self.assertEqual(msg.referer, "referer", "Wrong referer") - self.assertNotEqual(msg.ip, "-", "Wrong ip") + self.assertNotEqual(msg.address, "-", "Wrong ip") def test_bad_user_agent(self): self.start_all() @@ -183,7 +183,7 @@ def test_bad_user_agent(self): # Make sure that some fields are properly set self.assertEqual(msg.method, "GET", "Wrong method") self.assertEqual(msg.uri, "/some-uri", "Wrong uri") - self.assertNotEqual(msg.ip, "-", "Wrong ip") + self.assertNotEqual(msg.address, "-", "Wrong ip") # Ensure message is logged when request is rejected by frang @@ -216,4 +216,4 @@ def test_frang(self): self.assertEqual(msg.uri, "/longer-than-10-symbols-uri", "Wrong uri") self.assertEqual(msg.user_agent, "user-agent", "Wrong user-agent") self.assertEqual(msg.referer, "referer", "Wrong referer") - self.assertNotEqual(msg.ip, "-", "Wrong ip") + self.assertNotEqual(msg.address, "-", "Wrong ip") diff --git a/t_clickhouse/__init__.py b/t_clickhouse/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/t_clickhouse/test_clickhouse_logs.py b/t_clickhouse/test_clickhouse_logs.py new file mode 100644 index 000000000..461bd6159 --- /dev/null +++ b/t_clickhouse/test_clickhouse_logs.py @@ -0,0 +1,426 @@ +""" +Verify tfw_logger logging +""" + +import re +import time +from datetime import datetime, timezone +from ipaddress import IPv4Address + +import run_config +from helpers import tf_cfg +from test_suite import tester + +__author__ = "Tempesta Technologies, Inc." +__copyright__ = "Copyright (C) 2018-2025 Tempesta Technologies, Inc." +__license__ = "GPL2" + + +class TestClickhouseLogsBaseTest(tester.TempestaTest): + backends = [ + { + "id": "deproxy", + "type": "deproxy", + "port": "8000", + "response": "static", + "response_content": "HTTP/1.1 201 OK\r\n" "Content-Length: 8\r\n\r\n12345678", + }, + ] + tempesta = dict( + config=""" + listen 80; + server ${server_ip}:8000; + + access_log dmesg mmap mmap_host=${tfw_logger_clickhouse_host} mmap_log=${tfw_logger_daemon_log}; + """ + ) + clients = [ + { + "id": "deproxy", + "type": "deproxy", + "addr": "${tempesta_ip}", + "port": "80", + } + ] + + @staticmethod + def send_simple_request(deproxy_client, request=None, expected_status: str = "201") -> None: + """ + The simple request with 200-code response + """ + deproxy_client.send_request( + request=request or deproxy_client.create_request(method="GET", headers=[]), + expected_status_code=expected_status, + timeout=10, + ) + + def setUp(self): + super(TestClickhouseLogsBaseTest, self).setUp() + self.start_all_services(client=False) + + +class TestClickhouseLogsBufferConfiguration(TestClickhouseLogsBaseTest): + tempesta = dict( + config=""" + listen 80; + server ${server_ip}:8000; + + mmap_log_buffer_size 4096; + access_log dmesg mmap mmap_host=${tfw_logger_clickhouse_host} mmap_log=${tfw_logger_daemon_log}; + """ + ) + + def test_mmap_buffer(self): + """ + Check the buffer works fine + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request(client) + self.loggers.dmesg.update() + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 1) + + client.make_requests([client.create_request(method="GET", headers=[])] * 4100) + + self.assertTrue(client.wait_for_response()) + # buffer size + simple request before + self.assertEqual(self.loggers.clickhouse.access_log_records_count(), 4097) + + +class TestClickhouseLogsOnly(TestClickhouseLogsBaseTest): + tempesta = dict( + config=""" + listen 80; + server ${server_ip}:8000; + + access_log mmap mmap_host=${tfw_logger_clickhouse_host} mmap_log=${tfw_logger_daemon_log}; + """ + ) + + def test_dmesg_toggled_off(self): + """ + Toggle off the dmesg logs sending + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request(client) + self.loggers.dmesg.update() + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 0) + self.assertEqual(self.loggers.clickhouse.access_log_records_count(), 1) + + +class TestClickhouseTFWLoggerFile(TestClickhouseLogsBaseTest): + tempesta = dict( + config=""" + listen 80; + server ${server_ip}:8000; + + access_log mmap mmap_host=${tfw_logger_clickhouse_host} mmap_log=${tfw_logger_daemon_log}; + """ + ) + + def test_twf_logger_file(self): + """ + Check the content of tfw_logger daemon access log + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request(client) + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 0) + + tempesta = self.get_tempesta() + tempesta.stop() + + pattern = r".*Starting daemon.*Daemon started.*Stopping daemon.*Daemon stopped.*" + self.assertTrue(self.loggers.clickhouse.find(pattern)) + + +class BaseNoLogs(TestClickhouseLogsBaseTest): + def setUp(self): + super(TestClickhouseLogsBaseTest, self).setUp() + self.loggers.clickhouse.raise_error_on_logger_file_missing = False + self.start_all_services(client=False) + + def tearDown(self): + self.loggers.clickhouse.raise_error_on_logger_file_missing = True + + +class TestNoLogs(BaseNoLogs): + tempesta = dict( + config=""" + listen 80; + server ${server_ip}:8000; + """ + ) + + def test_dmesg_clickhouse_toggled_off(self): + """ + Turn off all the logs + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request(client) + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 0) + + self.assertFalse(self.loggers.clickhouse.tfw_log_file_exists()) + self.assertEqual(self.loggers.clickhouse.access_log_records_count(), 0) + + +class TestDmesgLogsOnly(BaseNoLogs): + tempesta = dict( + config=""" + listen 80; + server ${server_ip}:8000; + + access_log dmesg; + """ + ) + + def test_clickhouse_toggled_off(self): + """ + Turn on the only dmesg logging + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request(client) + self.loggers.dmesg.update() + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 1) + + self.assertFalse(self.loggers.clickhouse.tfw_log_file_exists()) + self.assertEqual(self.loggers.clickhouse.access_log_records_count(), 0) + + +class TestClickHouseLogsCorrectnessData(TestClickhouseLogsBaseTest): + tempesta = dict( + config=""" + listen 443 proto=https,h2; + server ${server_ip}:8000; + + tls_certificate ${tempesta_workdir}/tempesta.crt; + tls_certificate_key ${tempesta_workdir}/tempesta.key; + tls_match_any_server_name; + + access_log dmesg mmap mmap_host=${tfw_logger_clickhouse_host} mmap_log=${tfw_logger_daemon_log}; + """ + ) + clients = [ + {"id": "deproxy", "type": "deproxy", "addr": "${tempesta_ip}", "port": "443", "ssl": True} + ] + + def test_clickhouse_record_data(self): + """ + Verify the clickhouse log record data + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request( + client, + client.create_request( + uri="/test", + method="GET", + headers=[ + ( + "User-Agent", + "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:47.0) Gecko/20100101 Firefox/47.0", + ), + ("Referer", "https://somesite.com"), + ], + ), + ) + + self.loggers.dmesg.update() + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 1) + self.assertEqual(self.loggers.clickhouse.access_log_records_count(), 1) + + record = self.loggers.clickhouse.access_log_last_message() + t1 = record.timestamp.replace(microsecond=0, second=0, tzinfo=timezone.utc) + t2 = datetime.now(tz=timezone.utc).replace(microsecond=0, second=0) + self.assertEqual(t1, t2) + self.assertEqual( + record.user_agent, + "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:47.0) Gecko/20100101 Firefox/47.0", + ) + self.assertEqual(record.uri, "/test") + self.assertEqual(record.address, IPv4Address(tf_cfg.cfg.get("Client", "ip"))) + self.assertEqual(record.referer, "https://somesite.com") + self.assertEqual(record.status, 201) + self.assertEqual(record.version, 3) + self.assertEqual(record.method, 3) + self.assertEqual(record.response_content_length, 8) + self.assertEqual(record.dropped_events, 0) + self.assertEqual(record.vhost, "default") + self.assertEqual(record.ja5h, 2499671753152) + self.assertEqual(record.ja5t, 7407189765761859584) + + +class TestClickHouseLogsCorrectnessDataPostRequest(TestClickhouseLogsBaseTest): + backends = [ + {"id": "deproxy", "type": "deproxy", "port": "8000", "response": "static"}, + ] + + def setUp(self): + super().setUp() + + deproxy_server = self.get_server("deproxy") + deproxy_server.set_response( + "HTTP/1.1 500 Internal Server Error\r\n" "Content-Length: 8\r\n\r\n12345678" + ) + + def test_clickhouse_record_data_with_post(self): + """ + Verify the clickhouse log record data + """ + client = self.get_client("deproxy") + client.start() + + self.send_simple_request( + client, client.create_request(uri="/", method="POST", headers=[]), expected_status="500" + ) + + record = self.loggers.clickhouse.access_log_last_message() + self.assertEqual(record.status, 500) + self.assertEqual(record.method, 10) + self.assertEqual(record.response_content_length, 8) + self.assertEqual(record.dropped_events, 0) + + +class TestClickHouseLogsDelay(TestClickhouseLogsBaseTest): + def test_correctness_time_of_logs_after_server_delay(self): + """ + Verify the correctness of the clickhouse record + timestamp value and timezone, response time + """ + server = self.get_server("deproxy") + server.sleep_when_receiving_data = 2 + + client = self.get_client("deproxy") + client.start() + + time_before = datetime.now(tz=timezone.utc) + + self.send_simple_request(client) + self.loggers.dmesg.update() + + time_after = datetime.now(tz=timezone.utc) + self.assertEqual((time_after - time_before).seconds, 2) + self.assertEqual(self.loggers.dmesg.access_log_records_count(), 1) + self.assertEqual(self.loggers.clickhouse.access_log_records_count(), 1) + + record = self.loggers.clickhouse.access_log_last_message() + self.assertIsNone(record.timestamp.tzname()) + self.assertGreaterEqual(record.response_time, 2000) + + __time_after = time_after.replace(tzinfo=None, microsecond=0) + __record_time = record.timestamp.replace(microsecond=0) + self.assertEqual(__record_time, __time_after) + + +class TestClickHouseLogsUnderLoad(TestClickhouseLogsBaseTest): + clients = [ + { + "id": "h2load", + "type": "external", + "binary": "h2load", + "ssl": True, + "cmd_args": ( + " https://${tempesta_hostname}" + f" --clients {tf_cfg.cfg.get('General', 'concurrent_connections')}" + f" --threads {tf_cfg.cfg.get('General', 'stress_threads')}" + f" --max-concurrent-streams {tf_cfg.cfg.get('General', 'stress_requests_count')}" + f" --duration {tf_cfg.cfg.get('General', 'duration')}" + ), + }, + ] + tempesta = dict( + config=""" + listen 443 proto=h2,https; + server ${server_ip}:8000; + + tls_certificate ${tempesta_workdir}/tempesta.crt; + tls_certificate_key ${tempesta_workdir}/tempesta.key; + tls_match_any_server_name; + + access_log dmesg mmap mmap_host=${tfw_logger_clickhouse_host} mmap_log=${tfw_logger_daemon_log}; + + """ + ) + + def h2load_total_requests(self, text: str) -> int: + res = re.findall( + r"status codes: (\d*) 2xx, (\d*) 3xx, (\d*) 4xx, (\d*) 5xx", text, re.M | re.I + ) + return sum([int(requests) for requests in res[0]]) + + def test_all_logs_under_load(self): + client = self.get_client("h2load") + client.start() + + half_of_duration = run_config.DURATION / 2 + time.sleep(int(half_of_duration)) + + self.wait_while_busy(client) + client.stop() + + h2_total_requests = self.h2load_total_requests(client.stdout.decode()) + self.assertTrue(h2_total_requests) + + self.oops.update() + dmesg_logs_count = self.loggers.dmesg.access_log_records_count() + self.assertNotEqual(dmesg_logs_count, 0) + + clickhouse_collected_rows = self.loggers.clickhouse.access_log_records_count() + self.assertEqual(clickhouse_collected_rows, dmesg_logs_count) + self.assertEqual(h2_total_requests, dmesg_logs_count) + + def test_all_logs_with_reload(self): + client = self.get_client("h2load") + client.start() + + tempesta = self.get_tempesta() + + half_of_duration = run_config.DURATION / 2 + time.sleep(int(half_of_duration)) + tempesta.reload() + + self.wait_while_busy(client) + client.stop() + + h2_total_requests = self.h2load_total_requests(client.stdout.decode()) + self.assertTrue(h2_total_requests) + + dmesg_logs_records = self.loggers.dmesg.access_log_records_count() + self.assertNotEqual(dmesg_logs_records, 0) + + clickhouse_collected_rows = self.loggers.clickhouse.access_log_records_count() + self.assertEqual(clickhouse_collected_rows, dmesg_logs_records) + self.assertEqual(h2_total_requests, dmesg_logs_records) + + def test_tfw_logger_stop_cont(self): + client = self.get_client("h2load") + client.start() + + half_of_duration = run_config.DURATION / 2 + time.sleep(int(half_of_duration)) + + self.loggers.clickhouse.tfw_logger_signal("STOP") + self.loggers.clickhouse.tfw_logger_signal("CONT") + + self.wait_while_busy(client) + client.stop() + + h2_total_requests = self.h2load_total_requests(client.stdout.decode()) + self.assertTrue(h2_total_requests) + + dmesg_logs_records = self.loggers.dmesg.access_log_records_count() + self.assertNotEqual(dmesg_logs_records, 0) + + clickhouse_collected_rows = self.loggers.clickhouse.access_log_records_count() + self.assertLess(clickhouse_collected_rows, dmesg_logs_records) + self.assertGreater(clickhouse_collected_rows, 0) + self.assertEqual(h2_total_requests, dmesg_logs_records) diff --git a/test_suite/tester.py b/test_suite/tester.py index 1bf54d606..593056023 100644 --- a/test_suite/tester.py +++ b/test_suite/tester.py @@ -1,5 +1,6 @@ from __future__ import annotations, print_function +import dataclasses import datetime import os import re @@ -22,7 +23,7 @@ from framework.lxc_server import LXCServer, lxc_srv_factory from framework.nginx_server import Nginx, nginx_srv_factory from framework.stateful import Stateful -from helpers import control, dmesg, error, remote, tf_cfg, util +from helpers import clickhouse, control, dmesg, error, remote, tf_cfg, util from helpers.deproxy import dbg from helpers.util import fill_template from test_suite import sysnet @@ -99,6 +100,12 @@ def default_tempesta_factory(tempesta): register_backend("docker", docker_srv_factory) +@dataclasses.dataclass +class TempestaLoggers: + clickhouse: clickhouse.ClickHouseFinder + dmesg: dmesg.DmesgFinder + + class TempestaTest(unittest.TestCase): """Basic tempesta test class. Tempesta tests should have: @@ -323,6 +330,9 @@ def start_tempesta(self): if not self.__tempesta.is_running(): raise Exception("Can not start Tempesta") + if "mmap" in self.__tempesta.config.get_config(): + self.loggers.clickhouse.tfw_logger_wait_until_ready() + def start_all_clients(self): for cid in self.__clients: client = self.__clients[cid] @@ -351,6 +361,7 @@ def setUp(self): self._deproxy_auto_parser = DeproxyAutoParser(self.deproxy_manager) self.__save_memory_consumption() self.oops = dmesg.DmesgFinder() + self.loggers = TempestaLoggers(clickhouse=clickhouse.ClickHouseFinder(), dmesg=self.oops) self.oops_ignore = [] self.__create_servers() self.__create_tempesta() @@ -368,6 +379,9 @@ def setUp(self): def cleanup_services(self): tf_cfg.dbg(3, "\tCleanup: services") + self.loggers.clickhouse.tfw_log_file_remove() + self.loggers.clickhouse.access_log_clear() + for service in self.get_all_services(): service.stop() if service.exceptions: diff --git a/tests_config.ini.sample b/tests_config.ini.sample index b3c011f1b..e72b583fa 100644 --- a/tests_config.ini.sample +++ b/tests_config.ini.sample @@ -296,3 +296,44 @@ lxc_container_name = tempesta-site-stage # website_user and website_password - login and pwaaword for tempesta-tech.com tests. # It must exist in SQL dump in tempesta-tech repo. + +[TFW_Logger] +# Configuration of the TFW Logger daemon. +# The daemon is responsible for storing HTTP request logs in the ClickHouse database. +# It also maintains its own log file containing information about its lifespan. + +# The host of the Clickhouse Database +# +# ex.: clickhouse_host = localhost (default localhost) +# +clickhouse_host = localhost + +# The port of the Clickhouse Database +# +# ex.: clickhouse_port = 8123 (default 8123) +# +clickhouse_port = 8123 + +# The username of the Clickhouse Database +# +# ex.: clickhouse_username = default (default default) +# +clickhouse_username = default + +# The password of the Clickhouse Database +# +# ex.: clickhouse_password = password (default is empty) +# +clickhouse_password = + +# The database name of the Clickhouse Database +# +# ex.: clickhouse_database = my_database (default default) +# +clickhouse_database = default + +# The TFW Logger daemon log file path. +# +# ex.: daemon_log = /var/log/tfw_logger.log (default /tmp/tfw_logger.log) +# +daemon_log = /tmp/tfw_logger.log diff --git a/tests_disabled.json b/tests_disabled.json index 78dcb868d..905ee1e01 100644 --- a/tests_disabled.json +++ b/tests_disabled.json @@ -320,6 +320,18 @@ { "name": "t_ja5.test_ja5_filters.TestJa5FiltersTestSuiteCurves", "reason": "Only curve prime256v1 is available now" + }, + { + "name": "t_ja5.test_ja5_filters.TestJa5FiltersTestSuiteAlpn", + "reason": "Disabled by test issue #2329" + }, + { + "name": "t_clickhouse.test_clickhouse_logs.TestClickhouseLogsBufferConfiguration.test_mmap_buffer", + "reason": "Disabled by issue #2313" + }, + { + "name": "t_clickhouse.test_clickhouse_logs.TestClickHouseLogsUnderLoad", + "reason": "Disabled by issue #2314" } ] }