Bug #52452 for POE: Failed tests 8-10 in t/90_regression/neyuki

Fri Dec 04 21:46:56 2009 rdb [...] cpan.org - Ticket created

Subject:

Failed tests 8-10 in t/90_regression/neyuki_detach.t

Test Summary Report ------------------- t/90_regression/neyuki_detach.t (Wstat: 0 Tests: 10 Failed: 3) Failed tests: 8-10 Files=131, Tests=4046, 168 wallclock secs ( 1.26 usr 0.56 sys + 17.91 cusr 4.16 csys = 23.89 CPU) Result: FAIL Failed 1/131 test programs. 3/4046 subtests failed. System is very skeletal debian lenny, all updates applied. perl 5.10.0.

Sun Dec 27 13:48:30 2009 RCAPUTO [...] cpan.org - Correspondence added

On Fri Dec 04 21:46:56 2009, RDB wrote:
Show quoted text

> Test Summary Report
> -------------------
> t/90_regression/neyuki_detach.t (Wstat: 0 Tests: 10
> Failed: 3)
> Failed tests: 8-10
> Files=131, Tests=4046, 168 wallclock secs ( 1.26 usr 0.56 sys + 17.91
> cusr 4.16 csys = 23.89 CPU)
> Result: FAIL
> Failed 1/131 test programs. 3/4046 subtests failed.
>
>
> System is very skeletal debian lenny, all updates applied. perl 5.10.0.

I'm not seeing it here, and this is one of the pure-POE tests without strange system dependencies...

Sun Dec 27 13:48:32 2009 The RT System itself - Status changed from 'new' to 'open'

Mon Dec 28 16:26:57 2009 rdb [...] cpan.org - Correspondence added

On Sun Dec 27 13:48:30 2009, RCAPUTO wrote:
Show quoted text

> On Fri Dec 04 21:46:56 2009, RDB wrote:

> > Test Summary Report
> > -------------------
> > t/90_regression/neyuki_detach.t (Wstat: 0 Tests: 10
> > Failed: 3)
> > Failed tests: 8-10
> > Files=131, Tests=4046, 168 wallclock secs ( 1.26 usr 0.56 sys + 17.91 cusr 4.16 csys = 23.89 CPU)
> > Result: FAIL
> > Failed 1/131 test programs. 3/4046 subtests failed.
> >
> > System is very skeletal debian lenny, all updates applied. perl 5.10.0.

>
> I'm not seeing it here, and this is one of the pure-POE tests without
> strange system dependencies...

OK, looking at the test itself, the code has lots of:
print "not " unless $test == 8;
print "ok foo # foo happened\n";

Changing the output to be more verbose gives me:

not ok 8 # child is done (sequence 8, should be 9)
not ok 9 # child stopping (sequence 9 should be 10)
not ok 10 # stopping parent (sequence 10, should be 8)

If I read this right, the "error" is that the message are supposed to occur in this order:

stopping parent
child is done
child is stopping

but instead "stopping parent" is happening after the "child" messages.

I can't even tell you if that's bad. But it IS the cause of the test "failure."

Mon Dec 28 18:35:48 2009 RCAPUTO [...] cpan.org - Correspondence added

Is it possible that your tests are picking up a different version of POE? I know you said it was a bare-bones install, but it's hard to imagine this test failing.

Alternatively, is the system clock is rolling backwards?

On Mon Dec 28 16:26:57 2009, RDB wrote:
Show quoted text

> On Sun Dec 27 13:48:30 2009, RCAPUTO wrote:

> > On Fri Dec 04 21:46:56 2009, RDB wrote:

> > > Test Summary Report
> > > -------------------
> > > t/90_regression/neyuki_detach.t (Wstat: 0 Tests: 10
> > > Failed: 3)
> > > Failed tests: 8-10
> > > Files=131, Tests=4046, 168 wallclock secs ( 1.26 usr 0.56 sys +

> 17.91 cusr
> 4.16 csys = 23.89 CPU)

> > > Result: FAIL
> > > Failed 1/131 test programs. 3/4046 subtests failed.
> > >
> > > System is very skeletal debian lenny, all updates applied. perl

> 5.10.0.

> >
> > I'm not seeing it here, and this is one of the pure-POE tests

> without

> > strange system dependencies...

>
> OK, looking at the test itself, the code has lots of:
> print "not " unless $test == 8;
> print "ok foo # foo happened\n";
>
> Changing the output to be more verbose gives me:
>
> not ok 8 # child is done (sequence 8, should be 9)
> not ok 9 # child stopping (sequence 9 should be 10)
> not ok 10 # stopping parent (sequence 10, should be 8)
>
> If I read this right, the "error" is that the message are supposed to
> occur in
> this order:
>
> stopping parent
> child is done
> child is stopping
>
> but instead "stopping parent" is happening after the "child" messages.
>
> I can't even tell you if that's bad. But it IS the cause of the test
> "failure."

Thu Dec 31 14:17:56 2009 RCAPUTO [...] cpan.org - Correspondence added

I've taken my best guess at resolving this in revision 2767. I can't reproduce it anywhere, so I can't be sure I've really fixed it. Please reopen this ticket with more details if it persists (see my last reply).

Thu Dec 31 14:17:57 2009 RCAPUTO [...] cpan.org - Status changed from 'open' to 'resolved'

Wed Mar 10 17:00:08 2010 rdb [...] cpan.org - Status changed from 'resolved' to 'open'

Wed Mar 10 17:03:57 2010 rdb [...] cpan.org - Correspondence added

same distro, same stuff, different day. This is debian lenny, with all the latest packages, and NO POE installed beforehand. === First, the fail: perl -Ilib t/90_regression/neyuki_detach.t 1..12 ok 1 - starting parent in sequence ok 2 - parent spawning child in sequence ok 3 - child started in sequence ok 4 - parent received _child create in sequence ok 5 - child detached itself in sequence ok 6 - parent received _child lose in sequence ok 7 - child received _parent in sequence ok 8 - child parent is POE::Kernel ok 9 - parent done in sequence not ok 10 - child is done in sequence # Failed test 'child is done in sequence' # at t/90_regression/neyuki_detach.t line 86. # got: '9' # expected: '10' not ok 11 - child stopped in sequence # Failed test 'child stopped in sequence' # at t/90_regression/neyuki_detach.t line 66. # got: '10' # expected: '11' not ok 12 - stopping parent in sequence # Failed test 'stopping parent in sequence' # at t/90_regression/neyuki_detach.t line 30. # got: '11' # expected: '9' # Looks like you failed 3 tests of 12. === Next, perl -V: Summary of my perl5 (revision 5 version 10 subversion 0) configuration: Platform: osname=linux, osvers=2.6.30.5-dsa-amd64, archname=x86_64-linux-gnu-thread-multi uname='linux brahms 2.6.30.5-dsa-amd64 #1 smp mon aug 17 02:18:43 cest 2009 x86_64 gnulinux ' config_args='-Dusethreads -Duselargefiles -Dccflags=-DDEBIAN -Dcccdlflags=-fPIC -Darchname=x86_64-linux-gnu -Dprefix=/usr -Dprivlib=/usr/share/perl/5.10 -Darchlib=/usr/lib/perl/5.10 -Dvendorprefix=/usr -Dvendorlib=/usr/share/perl5 -Dvendorarch=/usr/lib/perl5 -Dsiteprefix=/usr/local -Dsitelib=/usr/local/share/perl/5.10.0 -Dsitearch=/usr/local/lib/perl/5.10.0 -Dman1dir=/usr/share/man/man1 -Dman3dir=/usr/share/man/man3 -Dsiteman1dir=/usr/local/man/man1 -Dsiteman3dir=/usr/local/man/man3 -Dman1ext=1 -Dman3ext=3perl -Dpager=/usr/bin/sensible-pager -Uafs -Ud_csh -Ud_ualarm -Uusesfio -Uusenm -DDEBUGGING=-g -Doptimize=-O2 -Duseshrplib -Dlibperl=libperl.so.5.10.0 -Dd_dosuid -des' hint=recommended, useposix=true, d_sigaction=define useithreads=define, usemultiplicity=define useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef use64bitint=define, use64bitall=define, uselongdouble=undef usemymalloc=n, bincompat5005=undef Compiler: cc='cc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64', optimize='-O2 -g', cppflags='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-aliasing -pipe -I/usr/local/include' ccversion='', gccversion='4.3.2', gccosandvers='' intsize=4, longsize=8, ptrsize=8, doublesize=8, byteorder=12345678 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16 ivtype='long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=8, prototype=define Linker and Libraries: ld='cc', ldflags =' -L/usr/local/lib' libpth=/usr/local/lib /lib /usr/lib /lib64 /usr/lib64 libs=-lgdbm -lgdbm_compat -ldb -ldl -lm -lpthread -lc -lcrypt perllibs=-ldl -lm -lpthread -lc -lcrypt libc=/lib/libc-2.7.so, so=so, useshrplib=true, libperl=libperl.so.5.10.0 gnulibc_version='2.7' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E' cccdlflags='-fPIC', lddlflags='-shared -O2 -g -L/usr/local/lib' Characteristics of this binary (from libperl): Compile-time options: MULTIPLICITY PERL_DONT_CREATE_GVSV PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP USE_64_BIT_ALL USE_64_BIT_INT USE_ITHREADS USE_LARGE_FILES USE_PERLIO USE_REENTRANT_API Built under linux Compiled at Aug 28 2009 22:24:50 %ENV: PERL5LIB="" PERL5OPT="" PERL5_CPANPLUS_IS_RUNNING="30841" PERL5_CPAN_IS_RUNNING="30841" @INC: /etc/perl /usr/local/lib/perl/5.10.0 /usr/local/share/perl/5.10.0 /usr/lib/perl5 /usr/share/perl5 /usr/lib/perl/5.10 /usr/share/perl/5.10 /usr/local/lib/site_perl . === $ cat /etc/debian_version 5.0.4

Mon Mar 22 02:09:42 2010 RCAPUTO [...] cpan.org - Correspondence added

On Wed Mar 10 17:03:57 2010, RDB wrote: Show quoted text

> same distro, same stuff, different day. > This is debian lenny, with all the latest packages, and NO POE > installed beforehand.

Ok. Is Time::HiRes::time() going backwards sometimes? NTP adjusting the clock back? If "now" isn't monotonic, then it could cause events to go out of order.

Wed Mar 24 15:22:53 2010 rdb [...] cpan.org - Correspondence added

On Mon Mar 22 02:09:42 2010, RCAPUTO wrote: Show quoted text

> On Wed Mar 10 17:03:57 2010, RDB wrote:

> > same distro, same stuff, different day. > > This is debian lenny, with all the latest packages, and NO POE > > installed beforehand.

> > Ok. Is Time::HiRes::time() going backwards sometimes? NTP

adjusting Show quoted text

> the clock back? If "now" isn't monotonic, then it could cause

events to Show quoted text

> go out of order.

I've updated the test, so that the things that SHOULD be in order are confirmed, and the things that have been getting slightly "out of order" but don't actually matter are ignored. Tests pass on both "known good" and the problem hosts.

Subject:

test.diff

--- t/90_regression/neyuki_detach.t 2009-12-31 11:15:01.000000000 -0800 +++ /home/rob/neyuki_detach.t 2010-03-24 11:57:42.000000000 -0700 @@ -18,6 +18,7 @@ use Test::More tests => 12; my $seq = 0; +my ($parent_done, $child_done); POE::Session->create( inline_states => { @@ -27,7 +28,7 @@ }, _stop => sub { - is(++$seq, 9, "stopping parent in sequence"); + ok($parent_done, "stopping parent in sequence"); }, _parent => sub { @@ -50,6 +51,7 @@ done => sub { is(++$seq, 8, "parent done in sequence"); + ++$parent_done; }, parent => sub { @@ -63,7 +65,7 @@ }, _stop => sub { - is(++$seq, 11, "child stopped in sequence"); + ok($child_done, "child stopped in sequence"); }, _parent => sub { @@ -83,7 +85,8 @@ }, done => sub { - is(++$seq, 10, "child is done in sequence"); + ok($parent_done, "child is done in sequence"); + ++$child_done; }, } );

Mon Jul 26 23:33:57 2010 RCAPUTO [...] cpan.org - Correspondence added

I'm mostly sure the test is correct. Relaxing the test requirements would allow incorrect event ordering, which I'd rather not do. I've made some fundamental changes to event dispatch order around revision 2900, +/- 20 revisions. Could you try this again with the latest "blead" POE?

Tue Jul 27 16:13:42 2010 RCAPUTO [...] cpan.org - Correspondence added

Rob Bloodgood reports that POE 1.291 resolves this test failure. Happy day! Thanks for your help with reporting and testing the bug.

Tue Jul 27 16:13:43 2010 RCAPUTO [...] cpan.org - Status changed from 'open' to 'resolved'

Bug #52452 for POE: Failed tests 8-10 in t/90_regression/neyuki_detach.t