Porting progress, failing tests
Jonas Tarnstrom
I had some progress today with the porting. I abstracted most win32
stuff and could build the project. The code looks kind of neat but I
think we could move the win32 stuff into some better place over time.
Anyways, failing tests.
When running testcore.py, I get these errors:
======================================================================
FAIL: testInterval (__main__.TestTasklet)
----------------------------------------------------------------------
Traceback (most recent call last):
File "testcore.py", line 188, in testInterval
self.assertEquals(3, len(count))
AssertionError: 3 != 0
======================================================================
FAIL: testJoinChildren (__main__.TestTasklet)
----------------------------------------------------------------------
Traceback (most recent call last):
File "testcore.py", line 134, in testJoinChildren
self.assertEquals(4, len(Tasklet.current().children()))
AssertionError: 4 != 5
======================================================================
FAIL: testTree (__main__.TestTasklet)
----------------------------------------------------------------------
Traceback (most recent call last):
File "testcore.py", line 159, in testTree
('child1', 2), ('child10', 3), ('child11', 3)]), flattened)
AssertionError: set([('child1', 2), ('child11', 3), ('child10', 3),
('child01', 3), ('child', 1), ('child0', 2), ('child00', 3)]) != set
([('child1', 2), ('child11', 3), ('child10', 3), ('_interval', 1),
('child01', 3), ('child', 1), ('child0', 2), ('child00', 3)])
----------------------------------------------------------------------
Ran 21 tests in 24.011s
FAILED (failures=3)
------------------------------8<-------------------------------------------------------------
Any ideas how this could be related to win32 or the porting in
general? I am using stackless 2.6.4
//Regards JT
Jonas Tarnstrom
I am very puzzled as it looks like a race condition in an application
without native threads.
Here's what happens, in the testInterval test at line 184:
------8<----------------------------
try:
Tasklet.join(ival_task, 3.0)
except TimeoutError:
#expect 3 counts, because interval started immediately
self.assertEquals(3, len(count))
------8<----------------------------
What happens is that the join returns instantaneous this not
fulfilling the assertions requirment (len is 0).
Bellow is a log with debugging enabled in libevent which shows what
happens, in this case it doesn't work:
C:\Programming\work\concurrence-win32\concurrence\test>python
testcore.py TestTasklet.testInterval
winsock_init: Got call!
DEBUG:root:test will timeout in 100.0 seconds
[debug] event_add: event: 01F6512C, call 10001000
[debug] evsignal_add: 01F6512C: changing signal handler
[debug] _evsignal_set_handler: evsignal (2) >= sh_old_max (0),
resizing
[debug] event_add: event: 01F8DA10, EV_READ call 10005210
[debug] win32_insert: adding event for 220
[debug] event_add: event: 01F6521C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] event_add: event: 01F65294, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 100 seconds, call 10001000
DEBUG:root:setUp testInterval (__main__.TestTasklet)
[debug] event_add: event: 01F65384, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 3 seconds, call 10001000
[debug] event_add: event: 01F653FC, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F6521C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F6521C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_add: event: 01F6521C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F653FC, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F653FC, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 01F653FC, callback 10001000
[debug] event_add: event: 01F65474, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F6521C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F6521C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 01F653FC, callback 10001000
[debug] event_add: event: 01F6521C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F65474, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F65474, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 01F65474, callback 10001000
[debug] event_add: event: 01F653FC, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F6521C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F6521C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 01F65474, callback 10001000
[debug] event_add: event: 01F6521C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F65384, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F653FC, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F65384, callback 10001000
[debug] event_del: 01F653FC, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 01F65384, callback 10001000
[debug] event_del: 01F653FC, callback 10001000
[debug] event_del: 01F653FC, callback 10001000
[debug] event_add: event: 01F653FC, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 3 seconds, call 10001000
[debug] event_del: 01F65384, callback 10001000
[debug] event_del: 01F653FC, callback 10001000
F[debug] event_add: event: 01F655DC, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 0 seconds, call 10001000
[debug] win32_dispatch: select returned 0
[debug] event_del: 01F655DC, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 01F655DC, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 01F653FC, callback 10001000
[debug] event_del: 01F655DC, callback 10001000
DEBUG:root:tearDown testInterval (__main__.TestTasklet), tasklet count
#3
======================================================================
FAIL: testInterval (__main__.TestTasklet)
----------------------------------------------------------------------
Traceback (most recent call last):
File "testcore.py", line 188, in testInterval
self.assertEquals(3, len(count))
AssertionError: 3 != 0
----------------------------------------------------------------------
Ran 1 test in 3.004s
FAILED (failures=1)
[debug] event_del: 01F655DC, callback 10001000
[debug] event_del: 01F6512C, callback 10001000
[debug] evsignal_del: 01F6512C: restoring signal handler
[debug] event_del: 01F6512C, callback 10001000
[debug] event_del: 01F6521C, callback 10001000
[debug] event_del: 01F6521C, callback 10001000
------------------------------8<--------------------------------------
Notice these lines:
F[debug] event_add: event: 01F655DC, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 0 seconds, call 10001000
"F" in front of debug makes it appears as if some printout didn't make
it to the console, such as "FATAL". No idea where that could have come
from. The line that follows schedules the 0 timeout, which can be
traced back from tearDown of the entire unittest.
Sometimes the tests do work without no modification what so ever with
no presence of the "F" sign in front of any line.
Log below is an example of a perfectly working test:
C:\Programming\work\concurrence-win32\concurrence\test>python
testcore.py TestTasklet.testInterval
winsock_init: Got call!
DEBUG:root:test will timeout in 100.0 seconds
[debug] event_add: event: 0210A03C, call 10001000
[debug] evsignal_add: 0210A03C: changing signal handler
[debug] _evsignal_set_handler: evsignal (2) >= sh_old_max (0),
resizing
[debug] event_add: event: 0213F848, EV_READ call 10005210
[debug] win32_insert: adding event for 208
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] event_add: event: 0210A1A4, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 100 seconds, call 10001000
DEBUG:root:setUp testInterval (__main__.TestTasklet)
[debug] event_add: event: 0210A294, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 3 seconds, call 10001000
[debug] event_add: event: 0210A30C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A12C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A30C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A30C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A30C, callback 10001000
[debug] event_add: event: 0210A384, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A12C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A30C, callback 10001000
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A384, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A384, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A384, callback 10001000
[debug] event_add: event: 0210A30C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A12C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A384, callback 10001000
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A294, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A294, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A294, callback 10001000
[debug] event_del: 0210A30C, callback 10001000
[debug] event_del: 0210A30C, callback 10001000
[debug] event_add: event: 0210A30C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 3 seconds, call 10001000
[debug] event_add: event: 0210A384, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A12C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A294, callback 10001000
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A384, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A384, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A384, callback 10001000
[debug] event_add: event: 0210A294, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A12C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A384, callback 10001000
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A294, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A294, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A294, callback 10001000
[debug] event_add: event: 0210A384, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A12C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A294, callback 10001000
[debug] event_add: event: 0210A12C, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 1 seconds, call 10001000
[debug] timeout_next: in 0 seconds
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A30C, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A30C, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A30C, callback 10001000
[debug] event_del: 0210A384, callback 10001000
[debug] event_del: 0210A384, callback 10001000
[debug] event_add: event: 0210A384, EV_TIMEOUT call 10001000
[debug] event_add: timeout in 0 seconds, call 10001000
[debug] win32_dispatch: select returned 0
[debug] event_del: 0210A384, callback 10001000
[debug] timeout_process: call 10001000
[debug] event_del: 0210A384, callback 10001000
[debug] event_base_loop: asked to terminate loop.
[debug] event_del: 0210A30C, callback 10001000
[debug] event_del: 0210A384, callback 10001000
DEBUG:root:tearDown testInterval (__main__.TestTasklet), tasklet count
#2
.
----------------------------------------------------------------------
Ran 1 test in 6.002s
OK
[debug] event_del: 0210A384, callback 10001000
[debug] event_del: 0210A03C, callback 10001000
[debug] evsignal_del: 0210A03C: restoring signal handler
[debug] event_del: 0210A03C, callback 10001000
[debug] event_del: 0210A12C, callback 10001000
[debug] event_del: 0210A12C, callback 10001000