Summary: On certain platforms, t/syslog.t suffers from intermittent failures in the tests of inet and udp connections. Given that Sys-Syslog is shipped with the Perl 5 core distribution, these test failures cause some smoke tests of the core to be graded FAIL.
Observations:
Today I had the occasion to build and test Perl 5 blead on OpenBSD for the first time in nine months. (Output of './perl -Ilib -V' for that build is attached.) The only test failures I got were in cpan/Sys-Syslog/t/syslog.t.
#####
...
Test Summary Report
-------------------
../cpan/Sys-Syslog/t/syslog.t (Wstat: 1024 Tests: 225 Failed: 4)
Failed tests: 145, 147, 189, 191
Non-zero exit status: 4
Files=2627, Tests=1090740, 654 wallclock secs (47.97 usr 113.67 sys + 553.14 cusr 297.98 csys = 1012.76 CPU)
Result: FAIL
#####
But when I ran that test by itself, I got a PASS!
I next installed Test-Smoke on this machine and conducted a smoke test. See: http://perl5.test-smoke.org/report/73009. Here I got failures in two individual tests -- but only one of them was among the tests which failed in my first test of blead! When I moved into the 'perl-current' directory -- the one where an individual smoke test run is actually executed -- and ran the test by itself, I got a PASS.
I next forked the Sys-Syslog repository on github.com and cloned the repo to this OpenBSD machine. In the master branch, I ran 'make test' and got a PASS. But when I ran 'prove -vb t/syslog.t' I got different results each time!
#####
# Run 1:
ok 144 - [inet] syslog() called with level 'info' (string)
ok 145 - [inet] syslog() should return true: '1'
not ok 146 - [inet] syslog() called with level 'info' (macro)
# Failed test '[inet] syslog() called with level 'info' (macro)'
# at t/syslog.t line 187.
# got: 'no connection to syslog available
# - udp connect: nobody listening
# - udp connect: nobody listening at t/syslog.t line 185.
# '
# expected: ''
not ok 147 - [inet] syslog() should return true: '0'
# Failed test '[inet] syslog() should return true: '0''
# at t/syslog.t line 188.
ok 148 - [inet] closelog()
ok 149 - [inet] closelog() should return true: '1'
ok 150 # skip can't use 'tcp' socket
ok 151 # skip can't use 'tcp' socket
...
ok 188 - [udp] syslog() called with level 'info' (string)
not ok 189 - [udp] syslog() should return true: '0'
ok 190 - [udp] syslog() called with level 'info' (macro)
ok 191 - [udp] syslog() should return true: '1'
ok 192 - [udp] closelog()
ok 193 - [udp] closelog() should return true: '1'
ok 194 # skip the 'unix' mechanism works, so the tests will likely fail with the 'stream' mechanism
...
# Failed test '[udp] syslog() should return true: '0''
# at t/syslog.t line 181.
# Looks like you failed 3 tests of 226.
Dubious, test returned 3 (wstat 768, 0x300)
Failed 3/226 subtests
(less 98 skipped subtests: 125 okay)
Test Summary Report
-------------------
t/syslog.t (Wstat: 768 Tests: 226 Failed: 3)
Failed tests: 146-147, 189
Non-zero exit status: 3
Files=1, Tests=226, 0 wallclock secs ( 0.03 usr 0.04 sys + 0.14 cusr 0.09 csys = 0.30 CPU)
Result: FAIL
#####
#####
Run 2:
ok 144 - [inet] syslog() called with level 'info' (string)
not ok 145 - [inet] syslog() should return true: '0'
not ok 146 - [inet] syslog() called with level 'info' (macro)
not ok 147 - [inet] syslog() should return true: '0'
ok 148 - [inet] closelog()
ok 149 - [inet] closelog() should return true: '1'
ok 150 # skip can't use 'tcp' socket
...
ok 188 # skip can't connect to syslog
ok 189 # skip can't connect to syslog
ok 190 # skip can't connect to syslog
#####
#####
Run 3:
PASS
# Here I noticed that I got the PASS because all tests in the ranges 134-149 and 176-193 were skipped with the message:
# skip can't connect to syslog
#####
#####
Run 4:
ok 144 - [inet] syslog() called with level 'info' (string)
not ok 145 - [inet] syslog() should return true: '0'
# Failed test '[inet] syslog() should return true: '0''
# at t/syslog.t line 181.
not ok 146 - [inet] syslog() called with level 'info' (macro)
# Failed test '[inet] syslog() called with level 'info' (macro)'
# at t/syslog.t line 187.
# got: 'no connection to syslog available
# - udp connect: nobody listening at t/syslog.t line 185.
# '
# expected: ''
not ok 147 - [inet] syslog() should return true: '0'
# Failed test '[inet] syslog() should return true: '0''
# at t/syslog.t line 188.
ok 148 - [inet] closelog()
ok 149 - [inet] closelog() should return true: '1'
ok 150 # skip can't use 'tcp' socket
...
ok 188 - [udp] syslog() called with level 'info' (string)
not ok 189 - [udp] syslog() should return true: '0'
# Failed test '[udp] syslog() should return true: '0''
# at t/syslog.t line 181.
not ok 190 - [udp] syslog() called with level 'info' (macro)
# Failed test '[udp] syslog() called with level 'info' (macro)'
# at t/syslog.t line 187.
# got: 'no connection to syslog available
# - udp connect: nobody listening at t/syslog.t line 185.
# '
# expected: ''
not ok 191 - [udp] syslog() should return true: '0'
# Failed test '[udp] syslog() should return true: '0''
# at t/syslog.t line 188.
ok 192 - [udp] closelog()
...
# Looks like you failed 6 tests of 226.
Dubious, test returned 6 (wstat 1536, 0x600)
Failed 6/226 subtests
(less 98 skipped subtests: 122 okay)
Test Summary Report
-------------------
t/syslog.t (Wstat: 1536 Tests: 226 Failed: 6)
Failed tests: 145-147, 189-191
Non-zero exit status: 6
#####
One of the reasons why these failures were so surprising was that other smoke tests of the Perl 5 core distribution on OpenBSD are not showing these failures. See: http://perl5.test-smoke.org/search; select "OpenBSD" for OS Name and "All versions" for Perl version. I can only speculate as to why that is so. Perhaps this machine -- a stock OpenBSD "box" from vagrantup.com -- is less robust than other OpenBSD smoke test machines.
We are, however, getting intermittent failures in cpan/Sys-Syslog/t/syslog.t on platforms other than BSD. See: http://perl5.test-smoke.org/submatrix?test=../cpan/Sys-Syslog/t/syslog.t
My overall impression was that the failures all occurred in tests which should have been SKIPped, i.e., tests ran -- and sometimes failed -- when they should not have run. This in turn implied that the results of statements like the following were incorrect:
#####
skip "can't connect to syslog", 18 if $@ =~ /^no connection to syslog available/;
#####
Whether SKIP conditions like the above were met seems to vary between runs. The variability is probably intensified by the fact that there is a large block of codes which feature nested SKIP conditions.
Recommendations:
I do not know enough about the various types of protocols being tested to fully diagnose the problem. However, I can tell you that the failures only occurred in the 'inet' and 'udp' iterations and only when those two protocols were tested in the same process with all the others. When I isolated the tests of the 'inet' and 'udp' protocols in a separate file, I got no failures in that file. Hence, I will be submitting a pull request along those lines.
Thank you very much.
Jim Keenan
| Subject: | perl_V.txt |
Summary of my perl5 (revision 5 version 29 subversion 5) configuration:
Commit id: 36b19dd8d51081b1314949c9e33ac02aac8aa273
Platform:
osname=openbsd
osvers=6.3
archname=OpenBSD.amd64-openbsd
uname='openbsd openbsd63.my.domain 6.3 generic.mp#107 amd64 '
config_args='-des -Dusedevel'
hint=recommended
useposix=true
d_sigaction=define
useithreads=undef
usemultiplicity=undef
use64bitint=define
use64bitall=define
uselongdouble=undef
usemymalloc=n
default_inc_excludes_dot=define
bincompat5005=undef
Compiler:
cc='cc'
ccflags ='-fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -D_FORTIFY_SOURCE=2'
optimize='-O2'
cppflags='-fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
ccversion=''
gccversion='4.2.1 Compatible OpenBSD Clang 5.0.1 (tags/RELEASE_501/final)'
gccosandvers=''
intsize=4
longsize=8
ptrsize=8
doublesize=8
byteorder=12345678
doublekind=3
d_longlong=define
longlongsize=8
d_longdbl=define
longdblsize=16
longdblkind=3
ivtype='long'
ivsize=8
nvtype='double'
nvsize=8
Off_t='off_t'
lseeksize=8
alignbytes=8
prototype=define
Linker and Libraries:
ld='cc'
ldflags ='-Wl,-E -fstack-protector-strong -L/usr/local/lib'
libpth=/usr/lib /usr/local/lib
libs=-lpthread -lm -lutil -lc
perllibs=-lpthread -lm -lutil -lc
libc=/usr/lib/libc.so.92.3
so=so
useshrplib=false
libperl=libperl.a
gnulibc_version=''
Dynamic Linking:
dlsrc=dl_dlopen.xs
dlext=so
d_dlsymun=undef
ccdlflags=' '
cccdlflags='-DPIC -fPIC '
lddlflags='-shared -fPIC -L/usr/local/lib -fstack-protector-strong'
Characteristics of this binary (from libperl):
Compile-time options:
HAS_TIMES
PERLIO_LAYERS
PERL_COPY_ON_WRITE
PERL_DONT_CREATE_GVSV
PERL_MALLOC_WRAP
PERL_OP_PARENT
PERL_PRESERVE_IVUV
PERL_USE_DEVEL
USE_64_BIT_ALL
USE_64_BIT_INT
USE_LARGE_FILES
USE_LOCALE
USE_LOCALE_COLLATE
USE_LOCALE_CTYPE
USE_LOCALE_NUMERIC
USE_LOCALE_TIME
USE_PERLIO
USE_PERL_ATOF
Built under openbsd
Compiled at Oct 25 2018 12:26:56
%ENV:
PERL2DIR="/home/jkeenan/gitwork/perl2"
PERL_WORKDIR="/home/jkeenan/gitwork/perl"
@INC:
lib
/usr/local/lib/perl5/site_perl/5.29.5/OpenBSD.amd64-openbsd
/usr/local/lib/perl5/site_perl/5.29.5
/usr/local/lib/perl5/5.29.5/OpenBSD.amd64-openbsd
/usr/local/lib/perl5/5.29.5