view stream_access_log.t @ 1951:1867428f1673

Tests: fixed h3_limit_req.t spurious failures. In the "reset stream - cancellation" test, HTTP/3 stream is closed without sending the request body when the request is waiting in the limit_req module, and this results in error 444. However, when the request is received with some minor delay due to system load, it is not delayed by limit_req, and the stream is closed during reading the request body, which results in error 400 instead, breaking the test. Fix is to introduce yet another request before the "reset stream" test, so the stream in question is always delayed by limit_req.
author Maxim Dounin <mdounin@mdounin.ru>
date Thu, 14 Mar 2024 02:25:49 +0300
parents f3ba4c74de31
children
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;

use Sys::Hostname;

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 {
    %%TEST_GLOBALS_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:$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;
        proxy_download_rate 2;
        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');

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+:0\.\d+:1\.\d+:1\.\d+/, '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('||', @_); }

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