Mercurial > hg > nginx-tests
view access_log.t @ 1291:3bc5df417f62
Tests: adjusted proxy variables time checks.
Strict ">= 1" check may fail if timekeeping is not precise, and sleep(1)
results in something like 0.999 time in headers. In particular, this
happens when using clock_gettime(CLOCK_MONOTONIC_COARSE) for ngx_current_msec
on Ubuntu 16.04. To fix this, sleep(1) replaced with select(1.1).
author | Maxim Dounin <mdounin@mdounin.ru> |
---|---|
date | Mon, 26 Feb 2018 18:09:32 +0300 |
parents | 7df2265e61be |
children | 5eb82b417fd6 |
line wrap: on
line source
#!/usr/bin/perl # (C) Nginx, Inc. # Tests for access_log. ############################################################################### use warnings; use strict; use Test::More; BEGIN { use FindBin; chdir($FindBin::Bin); } use lib 'lib'; use Test::Nginx; ############################################################################### select STDERR; $| = 1; select STDOUT; $| = 1; my $t = Test::Nginx->new()->has(qw/http rewrite gzip/)->plan(15) ->write_file_expand('nginx.conf', <<'EOF'); %%TEST_GLOBALS%% daemon off; events { } http { %%TEST_GLOBALS_HTTP%% log_format test "$uri:$status"; log_format long "long line $uri:$status"; log_format binary $binary_remote_addr; server { listen 127.0.0.1:8080; server_name localhost; location /combined { access_log %%TESTDIR%%/combined.log; return 200 OK; location /combined/off { access_log off; return 200 OK; } } location /filtered { access_log %%TESTDIR%%/filtered.log test if=$arg_logme; return 200 OK; } location /filtered/complex { access_log %%TESTDIR%%/complex.log test if=$arg_logme$arg_logmetoo; return 200 OK; } location /filtered/noreuse { access_log %%TESTDIR%%/noreuse.log test buffer=16k if=$arg_a; access_log %%TESTDIR%%/noreuse.log test buffer=16k if=$arg_b; return 200 OK; } location /compressed { access_log %%TESTDIR%%/compressed.log test gzip buffer=1m flush=100ms; return 200 OK; } location /multi { access_log %%TESTDIR%%/multi1.log test; access_log %%TESTDIR%%/multi2.log test; access_log %%TESTDIR%%/long.log long; return 200 OK; } location /varlog { access_log %%TESTDIR%%/varlog_${arg_logname} test; return 200 OK; } location /cache { open_log_file_cache max=3 inactive=20s valid=1m min_uses=2; access_log %%TESTDIR%%/dir/cache_${arg_logname} test; return 200 OK; } location /binary { access_log %%TESTDIR%%/binary.log binary; } } } EOF my $d = $t->testdir(); mkdir "$d/dir"; $t->run(); ############################################################################### http_get('/combined'); http_get('/combined/off'); http_get('/filtered'); http_get('/filtered/empty?logme='); http_get('/filtered/zero?logme=0'); http_get('/filtered/good?logme=1'); http_get('/filtered/work?logme=yes'); http_get('/filtered/complex'); http_get('/filtered/complex/one?logme=1'); http_get('/filtered/complex/two?logmetoo=1'); http_get('/filtered/complex/either1?logme=A&logmetoo=B'); http_get('/filtered/complex/either2?logme=A'); http_get('/filtered/complex/either3?logmetoo=B'); http_get('/filtered/complex/either4?logme=0&logmetoo=0'); http_get('/filtered/complex/neither?logme=&logmetoo='); http_get('/filtered/noreuse1/zero?a=0'); http_get('/filtered/noreuse1/good?a=1'); http_get('/filtered/noreuse2/zero?b=0'); http_get('/filtered/noreuse2/good?b=1'); http_get('/compressed'); http_get('/multi'); http_get('/varlog'); http_get('/varlog?logname='); http_get('/varlog?logname=0'); http_get('/varlog?logname=filename'); http_get('/binary'); http_get('/cache?logname=lru'); http_get('/cache?logname=lru'); http_get('/cache?logname=once'); http_get('/cache?logname=first'); http_get('/cache?logname=first'); http_get('/cache?logname=second'); http_get('/cache?logname=second'); rename "$d/dir", "$d/dir_moved"; http_get('/cache?logname=lru'); http_get('/cache?logname=once'); http_get('/cache?logname=first'); http_get('/cache?logname=second'); rename "$d/dir_moved", "$d/dir"; # wait for file to appear with nonzero size thanks to the flush parameter for (1 .. 10) { last if -s "$d/compressed.log"; select undef, undef, undef, 0.1; } # verify that "gzip" parameter turns on compression my $log; SKIP: { eval { require IO::Uncompress::Gunzip; }; skip("IO::Uncompress::Gunzip not installed", 1) if $@; my $gzipped = $t->read_file('compressed.log'); IO::Uncompress::Gunzip::gunzip(\$gzipped => \$log); like($log, qr!^/compressed:200!s, 'compressed log - flush time'); } # now verify all other logs $t->stop(); # verify that by default, 'combined' format is used, 'off' disables logging my $addr = IO::Socket::INET->new(LocalAddr => '127.0.0.1')->sockhost(); like($t->read_file('combined.log'), qr!^\Q$addr - - [\E .* \Q] "GET /combined HTTP/1.0" 200 2 "-" "-"\E$!x, 'default log format'); # verify that log filtering works $log = $t->read_file('filtered.log'); is($log, "/filtered/good:200\n/filtered/work:200\n", 'log filtering'); # verify "if=" argument works with complex value my $exp_complex = <<'EOF'; /filtered/complex/one:200 /filtered/complex/two:200 /filtered/complex/either1:200 /filtered/complex/either2:200 /filtered/complex/either3:200 /filtered/complex/either4:200 EOF is($t->read_file('complex.log'), $exp_complex, 'if with complex value'); # buffer created with false "if" is not reused among multiple access_log $log = $t->read_file('noreuse.log'); is($log, "/filtered/noreuse1/good:200\n/filtered/noreuse2/good:200\n", 'log filtering with buffering'); # multiple logs in a same location is($t->read_file('multi1.log'), "/multi:200\n", 'multiple logs 1'); # same content in the second log is($t->read_file('multi2.log'), "/multi:200\n", 'multiple logs 2'); is($t->read_file('long.log'), "long line /multi:200\n", 'long line format'); # test log destinations with variables is($t->read_file('varlog_0'), "/varlog:200\n", 'varlog literal zero name'); is($t->read_file('varlog_filename'), "/varlog:200\n", 'varlog good name'); # binary data is escaped # that's "\\x7F\\x00\\x00\\x01\n" in $binary_remote_addr for "127.0.0.1" my $expected = join '', map { sprintf "\\x%02X", $_ } split /\./, $addr; is($t->read_file('binary.log'), "$expected\n", 'binary'); SKIP: { skip 'win32', 4 if $^O eq 'MSWin32'; is(@{[$t->read_file('/dir/cache_lru') =~ /\//g]}, 2, 'cache - closed lru'); is(@{[$t->read_file('/dir/cache_once') =~ /\//g]}, 1, 'cache - min_uses'); is(@{[$t->read_file('/dir/cache_first') =~ /\//g]}, 3, 'cache - cached 1'); is(@{[$t->read_file('/dir/cache_second') =~ /\//g]}, 3, 'cache - cached 2'); } ###############################################################################