view stream_access_log.t @ 1263:ea3c7659b6c1

Tests: handled early pidfile write on win32 in the run() routine. In addition to the present waiting for pidfile, which is insufficient on win32 due to the CreateProcess model, and may lead to rare startup races, search now for the certain error message which indicates started worker process. This change allows tolerating moderate hiccups on win32 hosts.
author Sergey Kandaurov <pluknet@nginx.com>
date Tue, 19 Dec 2017 19:55:01 +0300
parents 766bcbb632ee
children 48c3964a10a5
line wrap: on
line source

#!/usr/bin/perl

# (C) Sergey Kandaurov
# (C) Nginx, Inc.

# Tests for stream access_log module and variables.

###############################################################################

use warnings;
use strict;

use Test::More;

BEGIN { use FindBin; chdir($FindBin::Bin); }

use lib 'lib';
use Test::Nginx;
use Test::Nginx::Stream qw/ stream /;

###############################################################################

select STDERR; $| = 1;
select STDOUT; $| = 1;

my $t = Test::Nginx->new()->has(qw/stream stream_map gzip/);

$t->write_file_expand('nginx.conf', <<'EOF');

%%TEST_GLOBALS%%

daemon off;

events {
}

stream {
    log_format  test  $server_addr;
    log_format  vars  $connection:$nginx_version:$hostname:$pid;
    log_format  addr  $binary_remote_addr:$remote_addr:$remote_port:
                      $server_addr:$server_port:$upstream_addr;
    log_format  date  $msec!$time_local!$time_iso8601;
    log_format  byte  $bytes_received:$bytes_sent:
                      $upstream_bytes_sent:$upstream_bytes_received;
    log_format  time  $upstream_connect_time:$upstream_first_byte_time:
                      $upstream_session_time;

    access_log  %%TESTDIR%%/off.log test;

    map $server_port $logme {
        %%PORT_8083%%  1;
        default        0;
    }

    server {
        listen      127.0.0.1:8081;
        proxy_pass  127.0.0.1:8080;
        access_log  off;
    }

    server {
        listen      127.0.0.1:8082;
        proxy_pass  127.0.0.1:8080;
        access_log  %%TESTDIR%%/time.log time;
    }

    server {
        listen      127.0.0.1:8083;
        listen      127.0.0.1:8084;
        proxy_pass  127.0.0.1:8080;
        access_log  %%TESTDIR%%/filtered.log test if=$logme;
    }

    server {
        listen      127.0.0.1:8085;
        proxy_pass  127.0.0.1:8080;
        access_log  %%TESTDIR%%/complex.log test if=$logme$logme;
    }

    server {
        listen      127.0.0.1:8086;
        proxy_pass  127.0.0.1:8080;
        access_log  %%TESTDIR%%/compressed.log test
                    gzip buffer=1m flush=100ms;
    }

    server {
        listen      127.0.0.1:8087;
        proxy_pass  127.0.0.1:8080;
        access_log  %%TESTDIR%%/varlog_$bytes_sent.log test;
    }

    server {
        listen      127.0.0.1:8088;
        proxy_pass  127.0.0.1:8080;
        access_log  %%TESTDIR%%/vars.log vars;
        access_log  %%TESTDIR%%/addr.log addr;
        access_log  %%TESTDIR%%/date.log date;
        access_log  %%TESTDIR%%/byte.log byte;
    }
}

EOF

$t->run_daemon(\&stream_daemon);
$t->run()->plan(10);

$t->waitforsocket('127.0.0.1:' . port(8080));

###############################################################################

my $str = 'SEE-THIS';

stream('127.0.0.1:' . port(8081))->io($str);
stream('127.0.0.1:' . port(8082))->io($str);
stream('127.0.0.1:' . port(8083))->io($str);
stream('127.0.0.1:' . port(8084))->io($str);
stream('127.0.0.1:' . port(8085))->io($str);
stream('127.0.0.1:' . port(8086))->io($str);
stream('127.0.0.1:' . port(8087))->io($str);

my $dport = port(8088);
my $s = stream("127.0.0.1:$dport");
my $lhost = $s->sockhost();
my $escaped = $s->sockaddr();
$escaped =~ s/([^\x20-\x7e])/sprintf('\\x%02X', ord($1))/gmxe;
my $lport = $s->sockport();
my $uport = port(8080);

$s->io($str);

# wait for file to appear with nonzero size thanks to the flush parameter

for (1 .. 10) {
	last if -s $t->testdir() . '/compressed.log';
	select undef, undef, undef, 0.1;
}

# verify that "gzip" parameter turns on compression

SKIP: {
	eval { require IO::Uncompress::Gunzip; };
	skip("IO::Uncompress::Gunzip not installed", 1) if $@;

	my $gzipped = $t->read_file('compressed.log');
	my $log;
	IO::Uncompress::Gunzip::gunzip(\$gzipped => \$log);
	like($log, qr/^127.0.0.1/, 'compressed log - flush time');
}

# now verify all other logs

$t->stop();

is($t->read_file('off.log'), '', 'log off');
is($t->read_file('filtered.log'), "127.0.0.1\n", 'log filtering');
ok($t->read_file('complex.log'), 'if with complex value');
ok($t->read_file('varlog_3.log'), 'variable in file');

chomp(my $hostname = lc `hostname`);
like($t->read_file('vars.log'), qr/^\d+:[\d.]+:$hostname:\d+$/, 'log vars');
is($t->read_file('addr.log'),
	"$escaped:$lhost:$lport:127.0.0.1:$dport:127.0.0.1:$uport\n",
	'log addr');
like($t->read_file('date.log'), qr#^\d+.\d+![-+\w/: ]+![-+\dT:]+$#, 'log date');
is($t->read_file('byte.log'), "8:3:8:3\n", 'log bytes');
like($t->read_file('time.log'), qr/0\.\d{3}:0\.\d{3}:0\.\d{3}/, 'log time');

###############################################################################

sub stream_daemon {
	my $server = IO::Socket::INET->new(
		Proto => 'tcp',
		LocalAddr => '127.0.0.1',
		LocalPort => port(8080),
		Listen => 5,
		Reuse => 1
	)
		or die "Can't create listening socket: $!\n";

	local $SIG{PIPE} = 'IGNORE';

	while (my $client = $server->accept()) {
		$client->autoflush(1);

		log2c("(new connection $client)");

		$client->sysread(my $buffer, 65536) or next;

		log2i("$client $buffer");

		$buffer = "ack";

		log2o("$client $buffer");

		$client->syswrite($buffer);

		close $client;
	}
}

sub log2i { Test::Nginx::log_core('|| <<', @_); }
sub log2o { Test::Nginx::log_core('|| >>', @_); }
sub log2c { Test::Nginx::log_core('||', @_); }

###############################################################################