2018-04-23 12:26:46 +00:00
|
|
|
import time
|
2020-05-15 03:20:56 +00:00
|
|
|
|
2020-10-07 22:18:43 +00:00
|
|
|
import pytest
|
2019-03-28 15:43:13 +00:00
|
|
|
from unit.applications.lang.python import TestApplicationPython
|
2020-12-06 16:01:59 +00:00
|
|
|
from unit.option import option
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-06-12 13:16:59 +00:00
|
|
|
prerequisites = {'modules': {'python': 'any'}}
|
2018-04-11 15:34:11 +00:00
|
|
|
|
|
|
|
|
2023-06-12 13:16:59 +00:00
|
|
|
class TestAccessLog(TestApplicationPython):
|
2018-04-11 15:34:11 +00:00
|
|
|
def load(self, script):
|
|
|
|
super().load(script)
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert 'success' in self.conf(
|
2023-02-21 17:21:29 +00:00
|
|
|
f'"{option.temp_dir}/access.log"', 'access_log'
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'access_log configure'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2022-07-28 13:13:03 +00:00
|
|
|
def set_format(self, format):
|
|
|
|
assert 'success' in self.conf(
|
|
|
|
{
|
2023-02-21 17:21:29 +00:00
|
|
|
'path': f'{option.temp_dir}/access.log',
|
2022-07-28 13:13:03 +00:00
|
|
|
'format': format,
|
|
|
|
},
|
|
|
|
'access_log',
|
|
|
|
), 'access_log format'
|
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_keepalive(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('mirror')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert self.get()['status'] == 200, 'init'
|
2019-04-09 17:59:35 +00:00
|
|
|
|
2023-05-25 13:26:12 +00:00
|
|
|
(_, sock) = self.post(
|
2019-03-26 20:38:30 +00:00
|
|
|
headers={
|
|
|
|
'Host': 'localhost',
|
|
|
|
'Connection': 'keep-alive',
|
|
|
|
},
|
|
|
|
start=True,
|
|
|
|
body='01234',
|
2019-04-09 17:59:35 +00:00
|
|
|
read_timeout=1,
|
2019-03-26 20:38:30 +00:00
|
|
|
)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"POST / HTTP/1.1" 200 5', 'access.log')
|
|
|
|
is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'keepalive 1'
|
2019-03-26 20:38:30 +00:00
|
|
|
|
2023-05-25 13:26:12 +00:00
|
|
|
_ = self.post(sock=sock, body='0123456789')
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"POST / HTTP/1.1" 200 10', 'access.log')
|
|
|
|
is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'keepalive 2'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_pipeline(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2019-03-26 20:38:30 +00:00
|
|
|
self.http(
|
|
|
|
b"""GET / HTTP/1.1
|
2018-04-11 15:34:11 +00:00
|
|
|
Host: localhost
|
|
|
|
Referer: Referer-1
|
|
|
|
|
|
|
|
GET / HTTP/1.1
|
|
|
|
Host: localhost
|
|
|
|
Referer: Referer-2
|
|
|
|
|
|
|
|
GET / HTTP/1.1
|
|
|
|
Host: localhost
|
|
|
|
Referer: Referer-3
|
|
|
|
Connection: close
|
|
|
|
|
2019-03-26 20:38:30 +00:00
|
|
|
""",
|
|
|
|
raw_resp=True,
|
|
|
|
raw=True,
|
|
|
|
)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'"GET / HTTP/1.1" 200 0 "Referer-1" "-"', 'access.log'
|
|
|
|
)
|
2020-09-16 20:31:15 +00:00
|
|
|
is not None
|
|
|
|
), 'pipeline 1'
|
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'"GET / HTTP/1.1" 200 0 "Referer-2" "-"', 'access.log'
|
|
|
|
)
|
2020-09-16 20:31:15 +00:00
|
|
|
is not None
|
|
|
|
), 'pipeline 2'
|
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'"GET / HTTP/1.1" 200 0 "Referer-3" "-"', 'access.log'
|
|
|
|
)
|
2020-09-16 20:31:15 +00:00
|
|
|
is not None
|
|
|
|
), 'pipeline 3'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_ipv6(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2021-01-14 03:04:20 +00:00
|
|
|
assert 'success' in self.conf(
|
|
|
|
{"[::1]:7080": {"pass": "applications/empty"}}, 'listeners'
|
|
|
|
)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
|
|
|
self.get(sock_type='ipv6')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'::1 - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"', 'access.log'
|
2020-09-16 20:31:15 +00:00
|
|
|
)
|
|
|
|
is not None
|
|
|
|
), 'ipv6'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_unix(self, temp_dir, wait_for_record):
|
2018-04-23 12:26:52 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2023-02-21 17:21:29 +00:00
|
|
|
addr = f'{temp_dir}/sock'
|
2018-04-23 12:26:52 +00:00
|
|
|
|
2021-01-14 03:04:20 +00:00
|
|
|
assert 'success' in self.conf(
|
2023-02-21 17:21:29 +00:00
|
|
|
{f'unix:{addr}': {"pass": "applications/empty"}}, 'listeners'
|
2019-10-23 13:05:52 +00:00
|
|
|
)
|
2018-04-23 12:26:52 +00:00
|
|
|
|
|
|
|
self.get(sock_type='unix', addr=addr)
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'unix: - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"', 'access.log'
|
2020-09-16 20:31:15 +00:00
|
|
|
)
|
|
|
|
is not None
|
|
|
|
), 'unix'
|
2018-04-23 12:26:52 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_referer(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2019-03-26 20:38:30 +00:00
|
|
|
self.get(
|
|
|
|
headers={
|
|
|
|
'Host': 'localhost',
|
|
|
|
'Referer': 'referer-value',
|
|
|
|
'Connection': 'close',
|
|
|
|
}
|
|
|
|
)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'"GET / HTTP/1.1" 200 0 "referer-value" "-"', 'access.log'
|
|
|
|
)
|
2020-09-16 20:31:15 +00:00
|
|
|
is not None
|
|
|
|
), 'referer'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_user_agent(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2019-03-26 20:38:30 +00:00
|
|
|
self.get(
|
|
|
|
headers={
|
|
|
|
'Host': 'localhost',
|
|
|
|
'User-Agent': 'user-agent-value',
|
|
|
|
'Connection': 'close',
|
|
|
|
}
|
|
|
|
)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'"GET / HTTP/1.1" 200 0 "-" "user-agent-value"', 'access.log'
|
2020-09-16 20:31:15 +00:00
|
|
|
)
|
|
|
|
is not None
|
|
|
|
), 'user agent'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_http10(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
|
|
|
self.get(http_10=True)
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"GET / HTTP/1.0" 200 0 "-" "-"', 'access.log')
|
|
|
|
is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'http 1.0'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_partial(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert self.post()['status'] == 200, 'init'
|
2019-04-15 12:52:32 +00:00
|
|
|
|
2023-05-25 13:26:12 +00:00
|
|
|
_ = self.http(b"""GE""", raw=True, read_timeout=1)
|
2019-08-01 15:15:00 +00:00
|
|
|
|
|
|
|
time.sleep(1)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"-" 400 0 "-" "-"', 'access.log') is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'partial'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_partial_2(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert self.post()['status'] == 200, 'init'
|
2019-04-15 12:52:32 +00:00
|
|
|
|
2019-04-22 15:52:35 +00:00
|
|
|
self.http(b"""GET /\n""", raw=True)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"-" 400 \d+ "-" "-"', 'access.log') is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'partial 2'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_partial_3(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert self.post()['status'] == 200, 'init'
|
2019-04-15 12:52:32 +00:00
|
|
|
|
2023-05-25 13:26:12 +00:00
|
|
|
_ = self.http(b"""GET / HTTP/1.1""", raw=True, read_timeout=1)
|
2019-08-01 15:15:00 +00:00
|
|
|
|
|
|
|
time.sleep(1)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"-" 400 0 "-" "-"', 'access.log') is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'partial 3'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_partial_4(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert self.post()['status'] == 200, 'init'
|
2019-04-15 12:52:32 +00:00
|
|
|
|
2023-05-25 13:26:12 +00:00
|
|
|
_ = self.http(b"""GET / HTTP/1.1\n""", raw=True, read_timeout=1)
|
2019-08-01 15:15:00 +00:00
|
|
|
|
|
|
|
time.sleep(1)
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"-" 400 0 "-" "-"', 'access.log') is not None
|
2020-09-16 20:31:15 +00:00
|
|
|
), 'partial 4'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
@pytest.mark.skip('not yet')
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_partial_5(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert self.post()['status'] == 200, 'init'
|
2019-04-09 17:59:35 +00:00
|
|
|
|
2019-04-22 15:52:35 +00:00
|
|
|
self.get(headers={'Connection': 'close'})
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"GET / HTTP/1.1" 400 \d+ "-" "-"', 'access.log')
|
2020-09-16 20:31:15 +00:00
|
|
|
is not None
|
|
|
|
), 'partial 5'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_get_parameters(self, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
|
|
|
self.get(url='/?blah&var=val')
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(
|
|
|
|
r'"GET /\?blah&var=val HTTP/1.1" 200 0 "-" "-"', 'access.log'
|
2020-09-16 20:31:15 +00:00
|
|
|
)
|
|
|
|
is not None
|
|
|
|
), 'get parameters'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_delete(self, search_in_file):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
2021-01-14 03:04:20 +00:00
|
|
|
assert 'success' in self.conf_delete('access_log')
|
2018-04-11 15:34:11 +00:00
|
|
|
|
|
|
|
self.get(url='/delete')
|
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
assert search_in_file(r'/delete', 'access.log') is None, 'delete'
|
2018-04-11 15:34:11 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_change(self, temp_dir, wait_for_record):
|
2018-04-11 15:34:11 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
|
|
|
self.get()
|
|
|
|
|
2023-02-21 17:21:29 +00:00
|
|
|
assert 'success' in self.conf(f'"{temp_dir}/new.log"', 'access_log')
|
2018-04-11 15:34:11 +00:00
|
|
|
|
|
|
|
self.get()
|
|
|
|
|
2020-09-16 20:31:15 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log')
|
2020-09-16 20:31:15 +00:00
|
|
|
is not None
|
|
|
|
), 'change'
|
2022-07-28 13:13:03 +00:00
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_format(self, wait_for_record):
|
2022-07-28 13:13:03 +00:00
|
|
|
self.load('empty')
|
|
|
|
|
|
|
|
def check_format(format, expect, url='/'):
|
|
|
|
self.set_format(format)
|
|
|
|
|
|
|
|
assert self.get(url=url)['status'] == 200
|
2023-05-29 15:45:49 +00:00
|
|
|
assert wait_for_record(expect, 'access.log') is not None, 'found'
|
2022-07-28 13:13:03 +00:00
|
|
|
|
|
|
|
format = 'BLAH\t0123456789'
|
|
|
|
check_format(format, format)
|
|
|
|
check_format('$uri $status $uri $status', '/ 200 / 200')
|
|
|
|
|
2023-05-29 15:45:49 +00:00
|
|
|
def test_access_log_variables(self, wait_for_record):
|
2022-07-28 13:13:03 +00:00
|
|
|
self.load('mirror')
|
|
|
|
|
|
|
|
# $body_bytes_sent
|
|
|
|
|
|
|
|
self.set_format('$uri $body_bytes_sent')
|
|
|
|
body = '0123456789' * 50
|
2022-09-07 00:11:04 +00:00
|
|
|
self.post(url='/bbs', body=body, read_timeout=1)
|
2022-07-28 13:13:03 +00:00
|
|
|
assert (
|
2023-05-29 15:45:49 +00:00
|
|
|
wait_for_record(fr'^\/bbs {len(body)}$', 'access.log') is not None
|
2022-07-28 13:13:03 +00:00
|
|
|
), '$body_bytes_sent'
|
|
|
|
|
2023-02-21 17:21:29 +00:00
|
|
|
def test_access_log_incorrect(self, temp_dir, skip_alert):
|
2022-07-28 13:13:03 +00:00
|
|
|
skip_alert(r'failed to apply new conf')
|
|
|
|
|
|
|
|
assert 'error' in self.conf(
|
2023-05-25 15:56:14 +00:00
|
|
|
f'{temp_dir}/blah/access.log',
|
2023-02-21 17:21:29 +00:00
|
|
|
'access_log/path',
|
2022-07-28 13:13:03 +00:00
|
|
|
), 'access_log path incorrect'
|
|
|
|
|
|
|
|
assert 'error' in self.conf(
|
|
|
|
{
|
2023-02-21 17:21:29 +00:00
|
|
|
'path': f'{temp_dir}/access.log',
|
2022-07-28 13:13:03 +00:00
|
|
|
'format': '$remote_add',
|
|
|
|
},
|
|
|
|
'access_log',
|
|
|
|
), 'access_log format incorrect'
|