Mercurial > hg > nginx-tests
view stream_access_log.t @ 1752:ba6e24e38f03
Tests: improved stop_daemons() to send signal again.
As was observed, it's possible that a signal to complete a uwsgi daemon
can be ignored while it is starting up, which results in tests hang due
to eternal waiting on child processes termination. Notably, it is seen
when running tests with a high number of prove jobs on a low-profile VM
against nginx with broken modules and/or configuration. To reproduce:
$ TEST_NGINX_GLOBALS=ERROR prove -j16 uwsgi*.t
Inspecting uwsgi under ktrace on FreeBSD confirms that a SIGTERM signal
is ignored at the very beginning of uwsgi startup. It is then replaced
with a default action after listen(), thus waiting until uwsgi is ready
to accept new TCP connections doesn't completely solve the hang window.
The fix is to retry sending a signal some time after waitpid(WNOHANG)
continuously demonstrated no progress with reaping a signaled process.
It is modelled after f13ead27f89c that improved stop() for nginx.
author | Sergey Kandaurov <pluknet@nginx.com> |
---|---|
date | Wed, 29 Dec 2021 22:29:23 +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('||', @_); } ###############################################################################