xref: /unit/test/test_access_log.py (revision 2168:c7c634e6dd30)
11635Szelenkov@nginx.comimport time
21635Szelenkov@nginx.com
31596Szelenkov@nginx.comimport pytest
41019Szelenkov@nginx.comfrom unit.applications.lang.python import TestApplicationPython
51730Szelenkov@nginx.comfrom unit.option import option
6634Szelenkov@nginx.com
71017Szelenkov@nginx.com
81019Szelenkov@nginx.comclass TestAccessLog(TestApplicationPython):
91467Szelenkov@nginx.com    prerequisites = {'modules': {'python': 'any'}}
10634Szelenkov@nginx.com
11634Szelenkov@nginx.com    def load(self, script):
12634Szelenkov@nginx.com        super().load(script)
13634Szelenkov@nginx.com
141596Szelenkov@nginx.com        assert 'success' in self.conf(
151654Szelenkov@nginx.com            '"' + option.temp_dir + '/access.log"', 'access_log'
161596Szelenkov@nginx.com        ), 'access_log configure'
17634Szelenkov@nginx.com
18*2168Szelenkov@nginx.com    def set_format(self, format):
19*2168Szelenkov@nginx.com        assert 'success' in self.conf(
20*2168Szelenkov@nginx.com            {
21*2168Szelenkov@nginx.com                'path': option.temp_dir + '/access.log',
22*2168Szelenkov@nginx.com                'format': format,
23*2168Szelenkov@nginx.com            },
24*2168Szelenkov@nginx.com            'access_log',
25*2168Szelenkov@nginx.com        ), 'access_log format'
26*2168Szelenkov@nginx.com
271028Szelenkov@nginx.com    def wait_for_record(self, pattern, name='access.log'):
281028Szelenkov@nginx.com        return super().wait_for_record(pattern, name)
29634Szelenkov@nginx.com
30634Szelenkov@nginx.com    def test_access_log_keepalive(self):
31634Szelenkov@nginx.com        self.load('mirror')
32634Szelenkov@nginx.com
331596Szelenkov@nginx.com        assert self.get()['status'] == 200, 'init'
341029Szelenkov@nginx.com
351017Szelenkov@nginx.com        (resp, sock) = self.post(
361017Szelenkov@nginx.com            headers={
371017Szelenkov@nginx.com                'Host': 'localhost',
381017Szelenkov@nginx.com                'Connection': 'keep-alive',
391017Szelenkov@nginx.com                'Content-Type': 'text/html',
401017Szelenkov@nginx.com            },
411017Szelenkov@nginx.com            start=True,
421017Szelenkov@nginx.com            body='01234',
431029Szelenkov@nginx.com            read_timeout=1,
441017Szelenkov@nginx.com        )
45634Szelenkov@nginx.com
461596Szelenkov@nginx.com        assert (
471596Szelenkov@nginx.com            self.wait_for_record(r'"POST / HTTP/1.1" 200 5') is not None
481596Szelenkov@nginx.com        ), 'keepalive 1'
49634Szelenkov@nginx.com
501017Szelenkov@nginx.com        resp = self.post(
511017Szelenkov@nginx.com            headers={
521017Szelenkov@nginx.com                'Host': 'localhost',
531017Szelenkov@nginx.com                'Connection': 'close',
541017Szelenkov@nginx.com                'Content-Type': 'text/html',
551017Szelenkov@nginx.com            },
561017Szelenkov@nginx.com            sock=sock,
571017Szelenkov@nginx.com            body='0123456789',
581017Szelenkov@nginx.com        )
59634Szelenkov@nginx.com
601596Szelenkov@nginx.com        assert (
611596Szelenkov@nginx.com            self.wait_for_record(r'"POST / HTTP/1.1" 200 10') is not None
621596Szelenkov@nginx.com        ), 'keepalive 2'
63634Szelenkov@nginx.com
64634Szelenkov@nginx.com    def test_access_log_pipeline(self):
65634Szelenkov@nginx.com        self.load('empty')
66634Szelenkov@nginx.com
671017Szelenkov@nginx.com        self.http(
681017Szelenkov@nginx.com            b"""GET / HTTP/1.1
69634Szelenkov@nginx.comHost: localhost
70634Szelenkov@nginx.comReferer: Referer-1
71634Szelenkov@nginx.com
72634Szelenkov@nginx.comGET / HTTP/1.1
73634Szelenkov@nginx.comHost: localhost
74634Szelenkov@nginx.comReferer: Referer-2
75634Szelenkov@nginx.com
76634Szelenkov@nginx.comGET / HTTP/1.1
77634Szelenkov@nginx.comHost: localhost
78634Szelenkov@nginx.comReferer: Referer-3
79634Szelenkov@nginx.comConnection: close
80634Szelenkov@nginx.com
811017Szelenkov@nginx.com""",
821017Szelenkov@nginx.com            raw_resp=True,
831017Szelenkov@nginx.com            raw=True,
841017Szelenkov@nginx.com        )
85634Szelenkov@nginx.com
861596Szelenkov@nginx.com        assert (
871596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-1" "-"')
881596Szelenkov@nginx.com            is not None
891596Szelenkov@nginx.com        ), 'pipeline 1'
901596Szelenkov@nginx.com        assert (
911596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-2" "-"')
921596Szelenkov@nginx.com            is not None
931596Szelenkov@nginx.com        ), 'pipeline 2'
941596Szelenkov@nginx.com        assert (
951596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-3" "-"')
961596Szelenkov@nginx.com            is not None
971596Szelenkov@nginx.com        ), 'pipeline 3'
98634Szelenkov@nginx.com
99634Szelenkov@nginx.com    def test_access_log_ipv6(self):
100634Szelenkov@nginx.com        self.load('empty')
101634Szelenkov@nginx.com
1021775Szelenkov@nginx.com        assert 'success' in self.conf(
1031775Szelenkov@nginx.com            {"[::1]:7080": {"pass": "applications/empty"}}, 'listeners'
1041775Szelenkov@nginx.com        )
105634Szelenkov@nginx.com
106634Szelenkov@nginx.com        self.get(sock_type='ipv6')
107634Szelenkov@nginx.com
1081596Szelenkov@nginx.com        assert (
1091028Szelenkov@nginx.com            self.wait_for_record(
1101017Szelenkov@nginx.com                r'::1 - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"'
1111596Szelenkov@nginx.com            )
1121596Szelenkov@nginx.com            is not None
1131596Szelenkov@nginx.com        ), 'ipv6'
114634Szelenkov@nginx.com
115658Szelenkov@nginx.com    def test_access_log_unix(self):
116658Szelenkov@nginx.com        self.load('empty')
117658Szelenkov@nginx.com
1181654Szelenkov@nginx.com        addr = option.temp_dir + '/sock'
119658Szelenkov@nginx.com
1201775Szelenkov@nginx.com        assert 'success' in self.conf(
1211245Szelenkov@nginx.com            {"unix:" + addr: {"pass": "applications/empty"}}, 'listeners'
1221245Szelenkov@nginx.com        )
123658Szelenkov@nginx.com
124658Szelenkov@nginx.com        self.get(sock_type='unix', addr=addr)
125658Szelenkov@nginx.com
1261596Szelenkov@nginx.com        assert (
1271028Szelenkov@nginx.com            self.wait_for_record(
1281017Szelenkov@nginx.com                r'unix: - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"'
1291596Szelenkov@nginx.com            )
1301596Szelenkov@nginx.com            is not None
1311596Szelenkov@nginx.com        ), 'unix'
132658Szelenkov@nginx.com
133634Szelenkov@nginx.com    def test_access_log_referer(self):
134634Szelenkov@nginx.com        self.load('empty')
135634Szelenkov@nginx.com
1361017Szelenkov@nginx.com        self.get(
1371017Szelenkov@nginx.com            headers={
1381017Szelenkov@nginx.com                'Host': 'localhost',
1391017Szelenkov@nginx.com                'Referer': 'referer-value',
1401017Szelenkov@nginx.com                'Connection': 'close',
1411017Szelenkov@nginx.com            }
1421017Szelenkov@nginx.com        )
143634Szelenkov@nginx.com
1441596Szelenkov@nginx.com        assert (
1451596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "referer-value" "-"')
1461596Szelenkov@nginx.com            is not None
1471596Szelenkov@nginx.com        ), 'referer'
148634Szelenkov@nginx.com
149634Szelenkov@nginx.com    def test_access_log_user_agent(self):
150634Szelenkov@nginx.com        self.load('empty')
151634Szelenkov@nginx.com
1521017Szelenkov@nginx.com        self.get(
1531017Szelenkov@nginx.com            headers={
1541017Szelenkov@nginx.com                'Host': 'localhost',
1551017Szelenkov@nginx.com                'User-Agent': 'user-agent-value',
1561017Szelenkov@nginx.com                'Connection': 'close',
1571017Szelenkov@nginx.com            }
1581017Szelenkov@nginx.com        )
159634Szelenkov@nginx.com
1601596Szelenkov@nginx.com        assert (
1611028Szelenkov@nginx.com            self.wait_for_record(
1621017Szelenkov@nginx.com                r'"GET / HTTP/1.1" 200 0 "-" "user-agent-value"'
1631596Szelenkov@nginx.com            )
1641596Szelenkov@nginx.com            is not None
1651596Szelenkov@nginx.com        ), 'user agent'
166634Szelenkov@nginx.com
167634Szelenkov@nginx.com    def test_access_log_http10(self):
168634Szelenkov@nginx.com        self.load('empty')
169634Szelenkov@nginx.com
170634Szelenkov@nginx.com        self.get(http_10=True)
171634Szelenkov@nginx.com
1721596Szelenkov@nginx.com        assert (
1731596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.0" 200 0 "-" "-"') is not None
1741596Szelenkov@nginx.com        ), 'http 1.0'
175634Szelenkov@nginx.com
176634Szelenkov@nginx.com    def test_access_log_partial(self):
177634Szelenkov@nginx.com        self.load('empty')
178634Szelenkov@nginx.com
1791596Szelenkov@nginx.com        assert self.post()['status'] == 200, 'init'
1801035Szelenkov@nginx.com
1811111Szelenkov@nginx.com        resp = self.http(b"""GE""", raw=True, read_timeout=1)
1821111Szelenkov@nginx.com
1831111Szelenkov@nginx.com        time.sleep(1)
184634Szelenkov@nginx.com
1851596Szelenkov@nginx.com        assert (
1861596Szelenkov@nginx.com            self.wait_for_record(r'"GE" 400 0 "-" "-"') is not None
1871596Szelenkov@nginx.com        ), 'partial'
188634Szelenkov@nginx.com
189634Szelenkov@nginx.com    def test_access_log_partial_2(self):
190634Szelenkov@nginx.com        self.load('empty')
191634Szelenkov@nginx.com
1921596Szelenkov@nginx.com        assert self.post()['status'] == 200, 'init'
1931035Szelenkov@nginx.com
1941043Szelenkov@nginx.com        self.http(b"""GET /\n""", raw=True)
195634Szelenkov@nginx.com
1961596Szelenkov@nginx.com        assert (
1971596Szelenkov@nginx.com            self.wait_for_record(r'"GET /" 400 \d+ "-" "-"') is not None
1981596Szelenkov@nginx.com        ), 'partial 2'
199634Szelenkov@nginx.com
200634Szelenkov@nginx.com    def test_access_log_partial_3(self):
201634Szelenkov@nginx.com        self.load('empty')
202634Szelenkov@nginx.com
2031596Szelenkov@nginx.com        assert self.post()['status'] == 200, 'init'
2041035Szelenkov@nginx.com
2051111Szelenkov@nginx.com        resp = self.http(b"""GET / HTTP/1.1""", raw=True, read_timeout=1)
2061111Szelenkov@nginx.com
2071111Szelenkov@nginx.com        time.sleep(1)
208634Szelenkov@nginx.com
2091596Szelenkov@nginx.com        assert (
2101596Szelenkov@nginx.com            self.wait_for_record(r'"GET /" 400 0 "-" "-"') is not None
2111596Szelenkov@nginx.com        ), 'partial 3'
212634Szelenkov@nginx.com
213634Szelenkov@nginx.com    def test_access_log_partial_4(self):
214634Szelenkov@nginx.com        self.load('empty')
215634Szelenkov@nginx.com
2161596Szelenkov@nginx.com        assert self.post()['status'] == 200, 'init'
2171035Szelenkov@nginx.com
2181111Szelenkov@nginx.com        resp = self.http(b"""GET / HTTP/1.1\n""", raw=True, read_timeout=1)
2191111Szelenkov@nginx.com
2201111Szelenkov@nginx.com        time.sleep(1)
221634Szelenkov@nginx.com
2221596Szelenkov@nginx.com        assert (
2231596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 400 0 "-" "-"') is not None
2241596Szelenkov@nginx.com        ), 'partial 4'
225634Szelenkov@nginx.com
2261596Szelenkov@nginx.com    @pytest.mark.skip('not yet')
227634Szelenkov@nginx.com    def test_access_log_partial_5(self):
228634Szelenkov@nginx.com        self.load('empty')
229634Szelenkov@nginx.com
2301596Szelenkov@nginx.com        assert self.post()['status'] == 200, 'init'
2311029Szelenkov@nginx.com
2321043Szelenkov@nginx.com        self.get(headers={'Connection': 'close'})
233634Szelenkov@nginx.com
2341596Szelenkov@nginx.com        assert (
2351596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 400 \d+ "-" "-"')
2361596Szelenkov@nginx.com            is not None
2371596Szelenkov@nginx.com        ), 'partial 5'
238634Szelenkov@nginx.com
239634Szelenkov@nginx.com    def test_access_log_get_parameters(self):
240634Szelenkov@nginx.com        self.load('empty')
241634Szelenkov@nginx.com
242634Szelenkov@nginx.com        self.get(url='/?blah&var=val')
243634Szelenkov@nginx.com
2441596Szelenkov@nginx.com        assert (
2451028Szelenkov@nginx.com            self.wait_for_record(
2461017Szelenkov@nginx.com                r'"GET /\?blah&var=val HTTP/1.1" 200 0 "-" "-"'
2471596Szelenkov@nginx.com            )
2481596Szelenkov@nginx.com            is not None
2491596Szelenkov@nginx.com        ), 'get parameters'
250634Szelenkov@nginx.com
251634Szelenkov@nginx.com    def test_access_log_delete(self):
252634Szelenkov@nginx.com        self.load('empty')
253634Szelenkov@nginx.com
2541775Szelenkov@nginx.com        assert 'success' in self.conf_delete('access_log')
255634Szelenkov@nginx.com
256634Szelenkov@nginx.com        self.get(url='/delete')
257634Szelenkov@nginx.com
2581596Szelenkov@nginx.com        assert self.search_in_log(r'/delete', 'access.log') is None, 'delete'
259634Szelenkov@nginx.com
2601850Smax.romanov@nginx.com    def test_access_log_change(self):
261634Szelenkov@nginx.com        self.load('empty')
262634Szelenkov@nginx.com
263634Szelenkov@nginx.com        self.get()
264634Szelenkov@nginx.com
2651775Szelenkov@nginx.com        assert 'success' in self.conf(
2661775Szelenkov@nginx.com            '"' + option.temp_dir + '/new.log"', 'access_log'
2671775Szelenkov@nginx.com        )
268634Szelenkov@nginx.com
269634Szelenkov@nginx.com        self.get()
270634Szelenkov@nginx.com
2711596Szelenkov@nginx.com        assert (
2721596Szelenkov@nginx.com            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log')
2731596Szelenkov@nginx.com            is not None
2741596Szelenkov@nginx.com        ), 'change'
275*2168Szelenkov@nginx.com
276*2168Szelenkov@nginx.com    def test_access_log_format(self):
277*2168Szelenkov@nginx.com        self.load('empty')
278*2168Szelenkov@nginx.com
279*2168Szelenkov@nginx.com        def check_format(format, expect, url='/'):
280*2168Szelenkov@nginx.com            self.set_format(format)
281*2168Szelenkov@nginx.com
282*2168Szelenkov@nginx.com            assert self.get(url=url)['status'] == 200
283*2168Szelenkov@nginx.com            assert self.wait_for_record(expect) is not None, 'found'
284*2168Szelenkov@nginx.com
285*2168Szelenkov@nginx.com        format = 'BLAH\t0123456789'
286*2168Szelenkov@nginx.com        check_format(format, format)
287*2168Szelenkov@nginx.com        check_format('$uri $status $uri $status', '/ 200 / 200')
288*2168Szelenkov@nginx.com
289*2168Szelenkov@nginx.com    def test_access_log_variables(self):
290*2168Szelenkov@nginx.com        self.load('mirror')
291*2168Szelenkov@nginx.com
292*2168Szelenkov@nginx.com        # $time_local
293*2168Szelenkov@nginx.com
294*2168Szelenkov@nginx.com        self.set_format('$uri $time_local $uri')
295*2168Szelenkov@nginx.com        assert self.get(url='/time_local')['status'] == 200
296*2168Szelenkov@nginx.com        assert self.wait_for_record('/time_local') is not None, 'time log'
297*2168Szelenkov@nginx.com        date = self.search_in_log(
298*2168Szelenkov@nginx.com            r'^\/time_local (.*) \/time_local$', 'access.log'
299*2168Szelenkov@nginx.com        )[1]
300*2168Szelenkov@nginx.com        assert (
301*2168Szelenkov@nginx.com            abs(
302*2168Szelenkov@nginx.com                self.date_to_sec_epoch(date, '%d/%b/%Y:%X %z')
303*2168Szelenkov@nginx.com                - time.mktime(time.localtime())
304*2168Szelenkov@nginx.com            )
305*2168Szelenkov@nginx.com            < 5
306*2168Szelenkov@nginx.com        ), '$time_local'
307*2168Szelenkov@nginx.com
308*2168Szelenkov@nginx.com        # $request_line
309*2168Szelenkov@nginx.com
310*2168Szelenkov@nginx.com        self.set_format('$request_line')
311*2168Szelenkov@nginx.com        assert self.get(url='/r_line')['status'] == 200
312*2168Szelenkov@nginx.com        assert self.wait_for_record(r'^GET \/r_line HTTP\/1\.1$') is not None
313*2168Szelenkov@nginx.com
314*2168Szelenkov@nginx.com        # $body_bytes_sent
315*2168Szelenkov@nginx.com
316*2168Szelenkov@nginx.com        self.set_format('$uri $body_bytes_sent')
317*2168Szelenkov@nginx.com        body = '0123456789' * 50
318*2168Szelenkov@nginx.com        self.post(
319*2168Szelenkov@nginx.com            url='/bbs',
320*2168Szelenkov@nginx.com            headers={
321*2168Szelenkov@nginx.com                'Host': 'localhost',
322*2168Szelenkov@nginx.com                'Connection': 'close',
323*2168Szelenkov@nginx.com                'Content-Type': 'text/html',
324*2168Szelenkov@nginx.com            },
325*2168Szelenkov@nginx.com            body=body,
326*2168Szelenkov@nginx.com            read_timeout=1,
327*2168Szelenkov@nginx.com        )
328*2168Szelenkov@nginx.com        assert (
329*2168Szelenkov@nginx.com            self.wait_for_record(r'^\/bbs ' + str(len(body)) + r'$') is not None
330*2168Szelenkov@nginx.com        ), '$body_bytes_sent'
331*2168Szelenkov@nginx.com
332*2168Szelenkov@nginx.com    def test_access_log_incorrect(self, skip_alert):
333*2168Szelenkov@nginx.com        skip_alert(r'failed to apply new conf')
334*2168Szelenkov@nginx.com
335*2168Szelenkov@nginx.com        assert 'error' in self.conf(
336*2168Szelenkov@nginx.com            option.temp_dir + '/blah/access.log' 'access_log/path',
337*2168Szelenkov@nginx.com        ), 'access_log path incorrect'
338*2168Szelenkov@nginx.com
339*2168Szelenkov@nginx.com        assert 'error' in self.conf(
340*2168Szelenkov@nginx.com            {
341*2168Szelenkov@nginx.com                'path': option.temp_dir + '/access.log',
342*2168Szelenkov@nginx.com                'format': '$remote_add',
343*2168Szelenkov@nginx.com            },
344*2168Szelenkov@nginx.com            'access_log',
345*2168Szelenkov@nginx.com        ), 'access_log format incorrect'
346