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