Bug #28804 for POE: POE::Wheel::Run test results vary depending on the event loop

Sun Aug 12 17:00:49 2007 martijn [...] cpan.org - Ticket created

Subject:

bad Wheel::Run test

<+LotR> now to figure out why Loop::Glib fails one Wheel::Run test and hangs in the signals_rerun tests <+LotR> # Callback timing is different for Gtk. <+LotR> $heap->{flushes_expected}++ if ( <+LotR> exists $INC{'Gtk.pm'} and $heap->{label} eq 'string/pause_resume' <+LotR> ); <+LotR> that might be cause of the Wheel::Run one <+LotR> dngor: you remember this: http://poe.svn.sourceforge.net/viewvc/poe?view=rev&revision=2092 <+LotR> how did you check Gtk wasn't just doing something wrong? <@dngor> If I recall correctly, it was after a few hours of debugging. <@dngor> That change compromises the tests. I'd prefer a better fix. * LotR s/hours/weeks/ for the guestimate on when he'll understand stuff sufficiently to come up with something <+LotR> (hehe, using s/// as a verb doesn't seem to work well) <@dngor> Well, does including Glib in that "fix" the test? <+LotR> yes <@dngor> Hm. <+nopaste> Someone at 62.131.36.85 pasted "not ok 99 - string/pause_resum" (18 lines) at http://nopaste.snit.ch:8001/10858 <@dngor> File a bug against the test. Maybe a fresh look will come up with a better fix.

Thu Nov 15 15:58:13 2007 AGRUNDMA [...] cpan.org - Correspondence added

From:

AGRUNDMA [...] cpan.org

I ran into the same issue while working on the EV loop. The wheel_run test fails the same flush test with 7 instead of 6. I looked at it for a little while and ended up adding the same hack that the Glib loop uses.

Thu Nov 15 15:58:15 2007 The RT System itself - Status changed from 'new' to 'open'

Sat Mar 22 17:58:57 2008 RCAPUTO [...] cpan.org - Correspondence added

On Sun Aug 12 17:00:49 2007, MARTIJN wrote: Show quoted text

> <+LotR> dngor: you remember this: > http://poe.svn.sourceforge.net/viewvc/poe?view=rev&revision=2092

Here's a diff between normalized debugging output for the PoLo::Select and PoLo::Gtk runs for this test.

string/pause_resume: performing put state: out init string/pause_resume: performing put state: out init string/pause_resume: _start string/pause_resume: _start string/pause_resume: stdin flush string/pause_resume: stdin flush string/pause_resume: stdout out#: init string/pause_resume: stdout out#: init string/pause_resume: performing method state: pause_stdout string/pause_resume: performing method state: pause_stdout string/pause_resume: performing put state: out delayed1 string/pause_resume: performing put state: out delayed1 string/pause_resume: performing put state: err immediate1 string/pause_resume: performing put state: err immediate1 string/pause_resume: stdin flush string/pause_resume: stdin flush string/pause_resume: stderr err#: immediate1 string/pause_resume: stderr err#: immediate1 string/pause_resume: performing method state: pause_stderr string/pause_resume: performing method state: pause_stderr string/pause_resume: performing put state: err delayed2 string/pause_resume: performing put state: err delayed2 string/pause_resume: performing method state: resume_stdout string/pause_resume: performing method state: resume_stdout > string/pause_resume: stdin flush string/pause_resume: stdout out#: delayed1 string/pause_resume: stdout out#: delayed1 string/pause_resume: performing put state: out immediate2 string/pause_resume: performing put state: out immediate2 string/pause_resume: stdin flush string/pause_resume: stdin flush > string/pause_resume: stdout out#: immediate2 > string/pause_resume: performing method state: resume_stderr > string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: sigchld CHLD for # (#) string/pause_resume: stdout out#: immediate2 < string/pause_resume: performing method state: resume_stderr < string/pause_resume: stderr err#: delayed2 string/pause_resume: stderr err#: delayed2 string/pause_resume: performing put state: out immediate3 string/pause_resume: performing put state: out immediate3 string/pause_resume: sigchld CHLD for # (#) < string/pause_resume: stdin flush string/pause_resume: stdin flush string/pause_resume: stdout out#: immediate3 string/pause_resume: stdout out#: immediate3 string/pause_resume: performing put state: err immediate4 string/pause_resume: performing put state: err immediate4 string/pause_resume: stdin flush string/pause_resume: stdin flush string/pause_resume: stderr err#: immediate4 string/pause_resume: stderr err#: immediate4 string/pause_resume: performing put state: bye string/pause_resume: performing put state: bye string/pause_resume: stdin flush string/pause_resume: stdin flush string/pause_resume: read error 0: string/pause_resume: read error 0: string/pause_resume: read error 0: string/pause_resume: read error 0: string/pause_resume: close string/pause_resume: close string/pause_resume: _stop (#) string/pause_resume: _stop (#)

Thu Sep 03 23:33:03 2009 RCAPUTO [...] cpan.org - Subject changed from 'bad Wheel::Run test' to 'POE::Wheel::Run test results vary depending on the event loop'

Fri Sep 04 03:49:49 2009 RCAPUTO [...] cpan.org - Correspondence added

The "failing" loops are flushing "out delayed1" and "out immediate2" separately. We expect them to be combined and flushed at once, but the timing of some event loops triggers a flush of "out delayed1" before "out immediate2" can be buffered. 111 out init (1) 111 flushed 111 pause_stdout 111 out delayed1 (2) 111 err immediate1 (3) 111 flushed 111 pause_stderr 111 err delayed2 (4) 111 resume_stdout 111 flushed 111 out immediate2 (5) 111 flushed 111 resume_stderr 111 out immediate3 (6) 111 flushed 111 err immediate4 (7) 111 flushed 111 bye (8) 111 flushed POE::Loop::Select has less granular I/O, so it has a greater tendency to allow data to be buffered and combined. As a result, there's one fewer flush: 111 out init (1) 111 flushed 111 pause_stdout 111 out delayed1 (2) 111 err immediate1 (3) 111 flushed 111 pause_stderr 111 err delayed2 (4) 111 resume_stdout *** OUT DELAYED1 NOT FLUSHED HERE *** 111 out immediate2 (5) 111 flushed 111 resume_stderr 111 out immediate3 (6) 111 flushed 111 err immediate4 (7) 111 flushed 111 bye (8) 111 flushed I'm making the test more forgiving because not combining writes is technically okay behavior. Fix is committed as revision 2671.

Fri Sep 04 03:49:51 2009 RCAPUTO [...] cpan.org - Status changed from 'open' to 'resolved'