> On 22 Mar 2023, at 05:02, Maxim Dounin <mdounin@mdounin.ru> wrote:
>
> Hello!
>
> On Mon, Mar 20, 2023 at 06:13:34PM +0400, Sergey Kandaurov wrote:
>
>> # HG changeset patch
>> # User Sergey Kandaurov <pluknet@nginx.com>
>> # Date 1679321601 -14400
>> # Mon Mar 20 18:13:21 2023 +0400
>> # Node ID f3225ad9300ee2c11c0dec54b9605e67060b7347
>> # Parent 1e1d0f3874b0c5b1e399ec76b0198b5c9c265a36
>> Tests: run syslog and error_log tests on win32.
>>
>> They are supposed to work well now, no reason to skip them.
>
> It might be a good idea to explicitly mention why it wasn't
> supposed to work.

It wasn't supposed to work due to stderr tests, now fixed.
See full description below in the updated series.

>
>> An exception is logging to stderr.
>
> And why stderr is not supposed to.
>
> (Just in case, the culprit is CreateProcess(CREATE_NO_WINDOW) used
> when starting worker processes, which creates a process without a
> console. This probably can be improved to preserve console if
> logging to stderr is used.)

Thanks, applied to description.

>
>>
>> diff --git a/error_log.t b/error_log.t
>> --- a/error_log.t
>> +++ b/error_log.t
>> @@ -22,8 +22,6 @@ use Test::Nginx;
>> select STDERR; $| = 1;
>> select STDOUT; $| = 1;
>>
>> -plan(skip_all => 'win32') if $^O eq 'MSWin32';
>> -
>> my $t = Test::Nginx->new()->has(qw/http limit_req/)
>> ->plan(25)->write_file_expand('nginx.conf', <<'EOF');
>>
>> @@ -110,7 +108,7 @@ EOF
>> open OLDERR, ">&", \*STDERR;
>> open STDERR, '>', $t->testdir() . '/stderr' or die "Can't reopen STDERR: $!";
>> open my $stderr, '<', $t->testdir() . '/stderr'
>> - or die "Can't open stderr file: $!";
>> + or die "Can't open stderr file: $!" unless $^O eq 'MSWin32';
>
> It shouldn't be a problem to open the file on Windows. Though
> will require explicitly closing it at the end of the test, so the
> test suite will be able to remove the test directory in
> destructor.
>
> (In other tests this will also require reordering of daemon
> startup, to avoid leaking the descriptor to daemons.)

Applied too.

>> [..]
>> @@ -255,13 +259,16 @@ sub syslog_daemon {
>> LocalAddr => "127.0.0.1:$port"
>> );
>>
>> - open my $fh, '>', $t->testdir() . '/' . $file;
>> - select $fh; $| = 1;
>> + my $path = $t->testdir() . '/' . $file;
>> + open my $fh, '>', $path;
>> + close $fh;
>>
>> while (1) {
>> my $buffer;
>> $s->recv($buffer, 4096);
>> + open $fh, '>>', $path;
>> print $fh $buffer . "\n";
>> + close $fh;
>> }
>
> It might be a good idea to clarify in the commit log why this is
> needed. (Notably, that pseudo-processes created by Perl's fork()
> emulation on win32 cannot be gracefully stopped when they are
> blocked in a system call, and using kill('KILL') as nginx does
> seems to leave the files open.)

Well, I don't like this kind of open/close tango.
Reading syslog can be done in the main process, without
invoking pseudo-processes with their limitations.
This should work with minor number of syslog messages
as seen in tests. Below is updated series, syslog part
is extracted into a separate change.

# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1680046138 -14400
# Wed Mar 29 03:28:58 2023 +0400
# Node ID be1832cdf571d465aed741b7dcbd583cedc43365
# Parent 0351dee227a8341e442feeb03920a46b259adeb5
Tests: revised reading syslog messages with test daemon.

On win32, terminating test daemons blocked by a system call leads
to leaking file descriptors, which breaks temp directory removal.
See limitations of pseudo-processes used in Perl's fork() emulation.
Now it is replaced with reading syslog in the main process.

diff --git a/mail_error_log.t b/mail_error_log.t
--- a/mail_error_log.t
+++ b/mail_error_log.t
@@ -90,12 +90,16 @@ open my $stderr, '<', $t->testdir() . '/
or die "Can't open stderr file: $!";

$t->run_daemon(\&Test::Nginx::IMAP::imap_test_daemon);
-$t->run_daemon(\&syslog_daemon, port(8981), $t, 's_glob.log');
-$t->run_daemon(\&syslog_daemon, port(8982), $t, 's_info.log');
+
+my ($s_glob, $s_info) = map {
+ IO::Socket::INET->new(
+ Proto => 'udp',
+ LocalAddr => '127.0.0.1:' . port($_)
+ )
+ or die "Can't open syslog socket: $!";
+} 8981, 8982;

$t->waitforsocket('127.0.0.1:' . port(8144));
-$t->waitforfile($t->testdir . '/s_glob.log');
-$t->waitforfile($t->testdir . '/s_info.log');

$t->run();

@@ -124,16 +128,16 @@ is(lines($t, 'stderr', '[debug]'), 0, 's

like($t->read_file('e_glob.log'), qr!nginx/[.0-9]+!, 'error global');
like($t->read_file('e_glob2.log'), qr!nginx/[.0-9]+!, 'error global 2');
-is_deeply(levels($t, 'e_glob.log'), levels($t, 'e_glob2.log'),
- 'multiple error global');
+is_deeply(levels($t->read_file('e_glob.log')),
+ levels($t->read_file('e_glob2.log')), 'multiple error global');

# syslog

parse_syslog_message('syslog', get_syslog());

-is_deeply(levels($t, 's_glob.log'), levels($t, 'e_glob.log'),
+is_deeply(levels(read_syslog($s_glob)), levels($t->read_file('e_glob.log')),
'global syslog messages');
-is_deeply(levels($t, 's_info.log'), levels($t, 'e_info.log'),
+is_deeply(levels(read_syslog($s_info)), levels($t->read_file('e_info.log')),
'mail syslog messages');

###############################################################################
@@ -153,10 +157,10 @@ sub lines {
}

sub levels {
- my ($t, $file) = @_;
+ my ($file) = @_;
my %levels_hash;

- map { $levels_hash{$_}++; } ($t->read_file($file) =~ /(\[\w+\])/g);
+ map { $levels_hash{$_}++; } ($file =~ /(\[\w+\])/g);

return \%levels_hash;
}
@@ -193,6 +197,19 @@ sub get_syslog {
return $data;
}

+sub read_syslog {
+ my ($s) = @_;
+ my $data = '';
+
+ IO::Select->new($s)->can_read(1);
+ while (IO::Select->new($s)->can_read(0.1)) {
+ my $buffer;
+ sysread($s, $buffer, 4096);
+ $data .= $buffer;
+ }
+ return $data;
+}
+
sub parse_syslog_message {
my ($desc, $line) = @_;

@@ -246,23 +263,3 @@ SKIP: {
}

###############################################################################
-
-sub syslog_daemon {
- my ($port, $t, $file) = @_;
-
- my $s = IO::Socket::INET->new(
- Proto => 'udp',
- LocalAddr => "127.0.0.1:$port"
- );
-
- open my $fh, '>', $t->testdir() . '/' . $file;
- select $fh; $| = 1;
-
- while (1) {
- my $buffer;
- $s->recv($buffer, 4096);
- print $fh $buffer . "\n";
- }
-}
-
-###############################################################################
diff --git a/stream_error_log.t b/stream_error_log.t
--- a/stream_error_log.t
+++ b/stream_error_log.t
@@ -78,12 +78,16 @@ open my $stderr, '<', $t->testdir() . '/
or die "Can't open stderr file: $!";

$t->run_daemon(\&stream_daemon);
-$t->run_daemon(\&syslog_daemon, port(8983), $t, 's_glob.log');
-$t->run_daemon(\&syslog_daemon, port(8984), $t, 's_stream.log');
+
+my ($s_glob, $s_stream) = map {
+ IO::Socket::INET->new(
+ Proto => 'udp',
+ LocalAddr => '127.0.0.1:' . port($_)
+ )
+ or die "Can't open syslog socket: $!";
+} 8983, 8984;

$t->waitforsocket('127.0.0.1:' . port(8081));
-$t->waitforfile($t->testdir . '/s_glob.log');
-$t->waitforfile($t->testdir . '/s_stream.log');

$t->run();

@@ -111,17 +115,17 @@ is(lines($t, 'stderr', '[debug]'), 0, 's

like($t->read_file('e_glob.log'), qr!nginx/[.0-9]+!, 'error global');
like($t->read_file('e_glob2.log'), qr!nginx/[.0-9]+!, 'error global 2');
-is_deeply(levels($t, 'e_glob.log'), levels($t, 'e_glob2.log'),
- 'multiple error global');
+is_deeply(levels($t->read_file('e_glob.log')),
+ levels($t->read_file('e_glob2.log')), 'multiple error global');

# syslog

parse_syslog_message('syslog', get_syslog('data2', '127.0.0.1:' . port(8082),
port(8985)));

-is_deeply(levels($t, 's_glob.log'), levels($t, 'e_glob.log'),
+is_deeply(levels(read_syslog($s_glob)), levels($t->read_file('e_glob.log')),
'global syslog messages');
-is_deeply(levels($t, 's_stream.log'), levels($t, 'e_stream.log'),
+is_deeply(levels(read_syslog($s_stream)), levels($t->read_file('e_stream.log')),
'stream syslog messages');

# error_log context
@@ -161,10 +165,10 @@ sub lines {
}

sub levels {
- my ($t, $file) = @_;
+ my ($file) = @_;
my %levels_hash;

- map { $levels_hash{$_}++; } ($t->read_file($file) =~ /(\[\w+\])/g);
+ map { $levels_hash{$_}++; } ($file =~ /(\[\w+\])/g);

return \%levels_hash;
}
@@ -202,6 +206,19 @@ sub get_syslog {
return $data;
}

+sub read_syslog {
+ my ($s) = @_;
+ my $data = '';
+
+ IO::Select->new($s)->can_read(1);
+ while (IO::Select->new($s)->can_read(0.1)) {
+ my $buffer;
+ sysread($s, $buffer, 4096);
+ $data .= $buffer;
+ }
+ return $data;
+}
+
sub parse_syslog_message {
my ($desc, $line) = @_;

@@ -256,24 +273,6 @@ SKIP: {

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

-sub syslog_daemon {
- my ($port, $t, $file) = @_;
-
- my $s = IO::Socket::INET->new(
- Proto => 'udp',
- LocalAddr => "127.0.0.1:$port"
- );
-
- open my $fh, '>', $t->testdir() . '/' . $file;
- select $fh; $| = 1;
-
- while (1) {
- my $buffer;
- $s->recv($buffer, 4096);
- print $fh $buffer . "\n";
- }
-}
-
sub stream_daemon {
my $server = IO::Socket::INET->new(
Proto => 'tcp',
diff --git a/syslog.t b/syslog.t
--- a/syslog.t
+++ b/syslog.t
@@ -25,8 +25,6 @@ use Test::Nginx;
select STDERR; $| = 1;
select STDOUT; $| = 1;

-plan(skip_all => 'win32') if $^O eq 'MSWin32';
-
my $t = Test::Nginx->new()->has(qw/http limit_req/)->plan(62);

$t->write_file_expand('nginx.conf', <<'EOF');
@@ -142,13 +140,13 @@ http {

EOF

-$t->run_daemon(\&syslog_daemon, port(8981), $t, 's_glob.log');
-$t->run_daemon(\&syslog_daemon, port(8982), $t, 's_http.log');
-$t->run_daemon(\&syslog_daemon, port(8983), $t, 's_if.log');
-
-$t->waitforfile($t->testdir . '/s_glob.log');
-$t->waitforfile($t->testdir . '/s_http.log');
-$t->waitforfile($t->testdir . '/s_if.log');
+my ($s_glob, $s_http, $s_if) = map {
+ IO::Socket::INET->new(
+ Proto => 'udp',
+ LocalAddr => '127.0.0.1:' . port($_)
+ )
+ or die "Can't open syslog socket: $!";
+} 8981, 8982, 8983;

$t->run();

@@ -186,7 +184,6 @@ is($lines[1], $lines[2], 'error_log many
# error_log log levels

SKIP: {
-
skip "no --with-debug", 1 unless $t->has_module('--with-debug');

isnt(syslog_lines('/debug', '[debug]'), 0, 'debug');
@@ -210,8 +207,10 @@ is(syslog_lines('/high', '[error]'), 1,

# check for the presence of the syslog messages in the global and http contexts

-is_deeply(levels($t, 's_glob.log'), levels($t, 'f_glob.log'), 'master syslog');
-is_deeply(levels($t, 's_http.log'), levels($t, 'f_http.log'), 'http syslog');
+is_deeply(levels(read_syslog($s_glob)), levels($t->read_file('f_glob.log')),
+ 'master syslog');
+is_deeply(levels(read_syslog($s_http)), levels($t->read_file('f_http.log')),
+ 'http syslog');

http_get('/if');
http_get('/if/empty?logme=');
@@ -219,11 +218,11 @@ http_get('/if/zero?logme=0');
http_get('/if/good?logme=1');
http_get('/if/work?logme=yes');

-get_syslog('/a');
+my $syslog_if = read_syslog($s_if);

-like($t->read_file('s_if.log'), qr/good:404/s, 'syslog if success');
-like($t->read_file('s_if.log'), qr/work:404/s, 'syslog if success 2');
-unlike($t->read_file('s_if.log'), qr/(if:|empty:|zero:)404/, 'syslog if fail');
+like($syslog_if, qr/good:404/s, 'syslog if success');
+like($syslog_if, qr/work:404/s, 'syslog if success 2');
+unlike($syslog_if, qr/(if:|empty:|zero:)404/, 'syslog if fail');

like(get_syslog('/nohostname'),
qr/^<(\d{1,3})> # PRI
@@ -258,10 +257,10 @@ sub syslog_lines {
}

sub levels {
- my ($t, $file) = @_;
+ my ($file) = @_;
my %levels_hash;

- map { $levels_hash{$_}++; } ($t->read_file($file) =~ /(\[\w+\])/g);
+ map { $levels_hash{$_}++; } ($file =~ /(\[\w+\])/g);

return \%levels_hash;
}
@@ -281,6 +280,19 @@ sub get_syslog {
return $data;
}

+sub read_syslog {
+ my ($s) = @_;
+ my $data = '';
+
+ IO::Select->new($s)->can_read(1);
+ while (IO::Select->new($s)->can_read(0.1)) {
+ my $buffer;
+ sysread($s, $buffer, 4096);
+ $data .= $buffer;
+ }
+ return $data;
+}
+
sub parse_syslog_message {
my ($desc, $line) = @_;

@@ -331,23 +343,3 @@ sub parse_syslog_message {
}

###############################################################################
-
-sub syslog_daemon {
- my ($port, $t, $file) = @_;
-
- my $s = IO::Socket::INET->new(
- Proto => 'udp',
- LocalAddr => "127.0.0.1:$port"
- );
-
- open my $fh, '>', $t->testdir() . '/' . $file;
- select $fh; $| = 1;
-
- while (1) {
- my $buffer;
- $s->recv($buffer, 4096);
- print $fh $buffer . "\n";
- }
-}
-
-###############################################################################
# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1680046139 -14400
# Wed Mar 29 03:28:59 2023 +0400
# Node ID 98fb93f9328c15b432d04fc372e0614c2c720f0a
# Parent be1832cdf571d465aed741b7dcbd583cedc43365
Tests: allow to run error_log tests on win32.

Tests are supposed to work now with stderr parts isolated.
In particular, leaking stderr file descriptor was fixed
to allow Test::Nginx destructor to remove temp directory.

Logging to stderr doesn't currently work in worker processes
on win32. This is caused by CreateProcess(CREATE_NO_WINDOW).
Such tests are marked TODO.

diff --git a/error_log.t b/error_log.t
--- a/error_log.t
+++ b/error_log.t
@@ -22,8 +22,6 @@ use Test::Nginx;
select STDERR; $| = 1;
select STDOUT; $| = 1;

-plan(skip_all => 'win32') if $^O eq 'MSWin32';
-
my $t = Test::Nginx->new()->has(qw/http limit_req/)
->plan(25)->write_file_expand('nginx.conf', <<'EOF');

@@ -123,40 +121,69 @@ open STDERR, ">&", \*OLDERR;
http_get('/');

SKIP: {
-
skip "no --with-debug", 3 unless $t->has_module('--with-debug');

http_get('/debug');
isnt(lines($t, 'e_debug_debug.log', '[debug]'), 0, 'file debug debug');
is(lines($t, 'e_debug_info.log', '[debug]'), 0, 'file debug info');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
isnt(lines($t, 'stderr', '[debug]'), 0, 'stderr debug');

}

+}
+
http_get('/info');
is(lines($t, 'e_info_debug.log', '[info]'), 1, 'file info debug');
is(lines($t, 'e_info_info.log', '[info]'), 1, 'file info info');
is(lines($t, 'e_info_notice.log', '[info]'), 0, 'file info notice');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
is(lines($t, 'stderr', '[info]'), 1, 'stderr info');

+}
+
http_get('/notice');
is(lines($t, 'e_notice_info.log', '[notice]'), 1, 'file notice info');
is(lines($t, 'e_notice_notice.log', '[notice]'), 1, 'file notice notice');
is(lines($t, 'e_notice_warn.log', '[notice]'), 0, 'file notice warn');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
is(lines($t, 'stderr', '[notice]'), 1, 'stderr notice');

+}
+
http_get('/warn');
is(lines($t, 'e_warn_notice.log', '[warn]'), 1, 'file warn notice');
is(lines($t, 'e_warn_warn.log', '[warn]'), 1, 'file warn warn');
is(lines($t, 'e_warn_error.log', '[warn]'), 0, 'file warn error');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
is(lines($t, 'stderr', '[warn]'), 1, 'stderr warn');

+}
+
http_get('/error');
is(lines($t, 'e_error_warn.log', '[error]'), 1, 'file error warn');
is(lines($t, 'e_error_error.log', '[error]'), 1, 'file error error');
is(lines($t, 'e_error_alert.log', '[error]'), 0, 'file error alert');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
is(lines($t, 'stderr', '[error]'), 1, 'stderr error');

+}
+
# count log messages emitted with various error_log levels

http_get('/file_low');
@@ -168,6 +195,9 @@ is(lines($t, 'e_multi.log', '[error]'),
http_get('/file_high');
is(lines($t, 'e_multi_high.log', '[error]'), 1, 'file high');

+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
http_get('/stderr_low');
is(lines($t, 'stderr', '[error]'), 2, 'stderr low');

@@ -177,6 +207,10 @@ is(lines($t, 'stderr', '[error]'), 2, 's
http_get('/stderr_high');
is(lines($t, 'stderr', '[error]'), 1, 'stderr high');

+}
+
+close $stderr;
+
###############################################################################

sub lines {
diff --git a/mail_error_log.t b/mail_error_log.t
--- a/mail_error_log.t
+++ b/mail_error_log.t
@@ -26,8 +26,6 @@ use Test::Nginx::IMAP;
select STDERR; $| = 1;
select STDOUT; $| = 1;

-plan(skip_all => 'win32') if $^O eq 'MSWin32';
-
my $t = Test::Nginx->new()->has(qw/mail imap http rewrite/);

$t->plan(30)->write_file_expand('nginx.conf', <<'EOF');
@@ -84,13 +82,13 @@ http {

EOF

+$t->run_daemon(\&Test::Nginx::IMAP::imap_test_daemon);
+
open OLDERR, ">&", \*STDERR;
open STDERR, '>', $t->testdir() . '/stderr' or die "Can't reopen STDERR: $!";
open my $stderr, '<', $t->testdir() . '/stderr'
or die "Can't open stderr file: $!";

-$t->run_daemon(\&Test::Nginx::IMAP::imap_test_daemon);
-
my ($s_glob, $s_info) = map {
IO::Socket::INET->new(
Proto => 'udp',
@@ -121,7 +119,14 @@ isnt(lines($t, 'e_debug.log', '[debug]')

isnt(lines($t, 'e_info.log', '[info]'), 0, 'file info in info');
is(lines($t, 'e_info.log', '[debug]'), 0, 'file debug in info');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
isnt(lines($t, 'stderr', '[info]'), 0, 'stderr info in info');
+
+}
+
is(lines($t, 'stderr', '[debug]'), 0, 'stderr debug in info');

# multiple error_log
@@ -140,6 +145,8 @@ is_deeply(levels(read_syslog($s_glob)),
is_deeply(levels(read_syslog($s_info)), levels($t->read_file('e_info.log')),
'mail syslog messages');

+close $stderr;
+
###############################################################################

sub lines {
diff --git a/stream_error_log.t b/stream_error_log.t
--- a/stream_error_log.t
+++ b/stream_error_log.t
@@ -26,8 +26,6 @@ use Test::Nginx::Stream qw/ stream /;
select STDERR; $| = 1;
select STDOUT; $| = 1;

-plan(skip_all => 'win32') if $^O eq 'MSWin32';
-
my $t = Test::Nginx->new()->has(qw/stream/)->plan(34);

$t->write_file_expand('nginx.conf', <<'EOF');
@@ -72,13 +70,13 @@ stream {

EOF

+$t->run_daemon(\&stream_daemon);
+
open OLDERR, ">&", \*STDERR;
open STDERR, '>', $t->testdir() . '/stderr' or die "Can't reopen STDERR: $!";
open my $stderr, '<', $t->testdir() . '/stderr'
or die "Can't open stderr file: $!";

-$t->run_daemon(\&stream_daemon);
-
my ($s_glob, $s_stream) = map {
IO::Socket::INET->new(
Proto => 'udp',
@@ -108,7 +106,14 @@ isnt(lines($t, 'e_debug.log', '[debug]')

isnt(lines($t, 'e_info.log', '[info]'), 0, 'file info in info');
is(lines($t, 'e_info.log', '[debug]'), 0, 'file debug in info');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
isnt(lines($t, 'stderr', '[info]'), 0, 'stderr info in info');
+
+}
+
is(lines($t, 'stderr', '[debug]'), 0, 'stderr debug in info');

# multiple error_log
@@ -139,8 +144,14 @@ my $msg = 'no live upstreams while conne

unlike($t->read_file('e_glob.log'), qr/$msg/ms, 'stream error in global');
like($t->read_file('e_info.log'), qr/$msg/ms, 'stream error in info');
+unlike($t->read_file('e_emerg.log'), qr/$msg/ms, 'stream error in emerg');
+
+TODO: {
+local $TODO = 'win32' if $^O eq 'MSWin32';
+
like($t->read_file('stderr'), qr/$msg/ms, 'stream error in info stderr');
-unlike($t->read_file('e_emerg.log'), qr/$msg/ms, 'stream error in emerg');
+
+}

$msg = "bytes from/to client:5/4, bytes from/to upstream:4/5";

@@ -148,6 +159,8 @@ like($t->read_file('e_stream.log'), qr/$

}

+close $stderr;
+
###############################################################################

sub lines {

--
Sergey Kandaurov
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
https://mailman.nginx.org/mailman/listinfo/nginx-devel