xref: /unit/test/test_access_log.py (revision 2190:fbfec2aaf4c3)
1import time
2
3import pytest
4from unit.applications.lang.python import TestApplicationPython
5from unit.option import option
6
7
8class TestAccessLog(TestApplicationPython):
9    prerequisites = {'modules': {'python': 'any'}}
10
11    def load(self, script):
12        super().load(script)
13
14        assert 'success' in self.conf(
15            '"' + option.temp_dir + '/access.log"', 'access_log'
16        ), 'access_log configure'
17
18    def set_format(self, format):
19        assert 'success' in self.conf(
20            {
21                'path': option.temp_dir + '/access.log',
22                'format': format,
23            },
24            'access_log',
25        ), 'access_log format'
26
27    def wait_for_record(self, pattern, name='access.log'):
28        return super().wait_for_record(pattern, name)
29
30    def test_access_log_keepalive(self):
31        self.load('mirror')
32
33        assert self.get()['status'] == 200, 'init'
34
35        (resp, sock) = self.post(
36            headers={
37                'Host': 'localhost',
38                'Connection': 'keep-alive',
39            },
40            start=True,
41            body='01234',
42            read_timeout=1,
43        )
44
45        assert (
46            self.wait_for_record(r'"POST / HTTP/1.1" 200 5') is not None
47        ), 'keepalive 1'
48
49        resp = self.post(sock=sock, body='0123456789')
50
51        assert (
52            self.wait_for_record(r'"POST / HTTP/1.1" 200 10') is not None
53        ), 'keepalive 2'
54
55    def test_access_log_pipeline(self):
56        self.load('empty')
57
58        self.http(
59            b"""GET / HTTP/1.1
60Host: localhost
61Referer: Referer-1
62
63GET / HTTP/1.1
64Host: localhost
65Referer: Referer-2
66
67GET / HTTP/1.1
68Host: localhost
69Referer: Referer-3
70Connection: close
71
72""",
73            raw_resp=True,
74            raw=True,
75        )
76
77        assert (
78            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-1" "-"')
79            is not None
80        ), 'pipeline 1'
81        assert (
82            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-2" "-"')
83            is not None
84        ), 'pipeline 2'
85        assert (
86            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-3" "-"')
87            is not None
88        ), 'pipeline 3'
89
90    def test_access_log_ipv6(self):
91        self.load('empty')
92
93        assert 'success' in self.conf(
94            {"[::1]:7080": {"pass": "applications/empty"}}, 'listeners'
95        )
96
97        self.get(sock_type='ipv6')
98
99        assert (
100            self.wait_for_record(
101                r'::1 - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"'
102            )
103            is not None
104        ), 'ipv6'
105
106    def test_access_log_unix(self):
107        self.load('empty')
108
109        addr = option.temp_dir + '/sock'
110
111        assert 'success' in self.conf(
112            {"unix:" + addr: {"pass": "applications/empty"}}, 'listeners'
113        )
114
115        self.get(sock_type='unix', addr=addr)
116
117        assert (
118            self.wait_for_record(
119                r'unix: - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"'
120            )
121            is not None
122        ), 'unix'
123
124    def test_access_log_referer(self):
125        self.load('empty')
126
127        self.get(
128            headers={
129                'Host': 'localhost',
130                'Referer': 'referer-value',
131                'Connection': 'close',
132            }
133        )
134
135        assert (
136            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "referer-value" "-"')
137            is not None
138        ), 'referer'
139
140    def test_access_log_user_agent(self):
141        self.load('empty')
142
143        self.get(
144            headers={
145                'Host': 'localhost',
146                'User-Agent': 'user-agent-value',
147                'Connection': 'close',
148            }
149        )
150
151        assert (
152            self.wait_for_record(
153                r'"GET / HTTP/1.1" 200 0 "-" "user-agent-value"'
154            )
155            is not None
156        ), 'user agent'
157
158    def test_access_log_http10(self):
159        self.load('empty')
160
161        self.get(http_10=True)
162
163        assert (
164            self.wait_for_record(r'"GET / HTTP/1.0" 200 0 "-" "-"') is not None
165        ), 'http 1.0'
166
167    def test_access_log_partial(self):
168        self.load('empty')
169
170        assert self.post()['status'] == 200, 'init'
171
172        resp = self.http(b"""GE""", raw=True, read_timeout=1)
173
174        time.sleep(1)
175
176        assert (
177            self.wait_for_record(r'"GE" 400 0 "-" "-"') is not None
178        ), 'partial'
179
180    def test_access_log_partial_2(self):
181        self.load('empty')
182
183        assert self.post()['status'] == 200, 'init'
184
185        self.http(b"""GET /\n""", raw=True)
186
187        assert (
188            self.wait_for_record(r'"GET /" 400 \d+ "-" "-"') is not None
189        ), 'partial 2'
190
191    def test_access_log_partial_3(self):
192        self.load('empty')
193
194        assert self.post()['status'] == 200, 'init'
195
196        resp = self.http(b"""GET / HTTP/1.1""", raw=True, read_timeout=1)
197
198        time.sleep(1)
199
200        assert (
201            self.wait_for_record(r'"GET /" 400 0 "-" "-"') is not None
202        ), 'partial 3'
203
204    def test_access_log_partial_4(self):
205        self.load('empty')
206
207        assert self.post()['status'] == 200, 'init'
208
209        resp = self.http(b"""GET / HTTP/1.1\n""", raw=True, read_timeout=1)
210
211        time.sleep(1)
212
213        assert (
214            self.wait_for_record(r'"GET / HTTP/1.1" 400 0 "-" "-"') is not None
215        ), 'partial 4'
216
217    @pytest.mark.skip('not yet')
218    def test_access_log_partial_5(self):
219        self.load('empty')
220
221        assert self.post()['status'] == 200, 'init'
222
223        self.get(headers={'Connection': 'close'})
224
225        assert (
226            self.wait_for_record(r'"GET / HTTP/1.1" 400 \d+ "-" "-"')
227            is not None
228        ), 'partial 5'
229
230    def test_access_log_get_parameters(self):
231        self.load('empty')
232
233        self.get(url='/?blah&var=val')
234
235        assert (
236            self.wait_for_record(
237                r'"GET /\?blah&var=val HTTP/1.1" 200 0 "-" "-"'
238            )
239            is not None
240        ), 'get parameters'
241
242    def test_access_log_delete(self):
243        self.load('empty')
244
245        assert 'success' in self.conf_delete('access_log')
246
247        self.get(url='/delete')
248
249        assert self.search_in_log(r'/delete', 'access.log') is None, 'delete'
250
251    def test_access_log_change(self):
252        self.load('empty')
253
254        self.get()
255
256        assert 'success' in self.conf(
257            '"' + option.temp_dir + '/new.log"', 'access_log'
258        )
259
260        self.get()
261
262        assert (
263            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log')
264            is not None
265        ), 'change'
266
267    def test_access_log_format(self):
268        self.load('empty')
269
270        def check_format(format, expect, url='/'):
271            self.set_format(format)
272
273            assert self.get(url=url)['status'] == 200
274            assert self.wait_for_record(expect) is not None, 'found'
275
276        format = 'BLAH\t0123456789'
277        check_format(format, format)
278        check_format('$uri $status $uri $status', '/ 200 / 200')
279
280    def test_access_log_variables(self):
281        self.load('mirror')
282
283        # $time_local
284
285        self.set_format('$uri $time_local $uri')
286        assert self.get(url='/time_local')['status'] == 200
287        assert self.wait_for_record('/time_local') is not None, 'time log'
288        date = self.search_in_log(
289            r'^\/time_local (.*) \/time_local$', 'access.log'
290        )[1]
291        assert (
292            abs(
293                self.date_to_sec_epoch(date, '%d/%b/%Y:%X %z')
294                - time.mktime(time.localtime())
295            )
296            < 5
297        ), '$time_local'
298
299        # $request_line
300
301        self.set_format('$request_line')
302        assert self.get(url='/r_line')['status'] == 200
303        assert self.wait_for_record(r'^GET \/r_line HTTP\/1\.1$') is not None
304
305        # $body_bytes_sent
306
307        self.set_format('$uri $body_bytes_sent')
308        body = '0123456789' * 50
309        self.post(url='/bbs', body=body, read_timeout=1)
310        assert (
311            self.wait_for_record(r'^\/bbs ' + str(len(body)) + r'$') is not None
312        ), '$body_bytes_sent'
313
314    def test_access_log_incorrect(self, skip_alert):
315        skip_alert(r'failed to apply new conf')
316
317        assert 'error' in self.conf(
318            option.temp_dir + '/blah/access.log' 'access_log/path',
319        ), 'access_log path incorrect'
320
321        assert 'error' in self.conf(
322            {
323                'path': option.temp_dir + '/access.log',
324                'format': '$remote_add',
325            },
326            'access_log',
327        ), 'access_log format incorrect'
328