[Zope3-dev] ZEO test failing under Cygwin

[Tim Peters]

[Godefroid Chapelle]
> Can you tell me what options or setup are needed so that I can send you
> logging info ?

I can tell you how to get logging info, but I don't want it mailed to me --
I can't promise to make time to look at it, and I don't have deep
understanding of this code anyway.  Jeremy has deep understanding but will
be gone most of this week.  Best bet is to post your log info here and hope
someone can make time to dig into it (assuming the cause doesn't become
apparent to you first).

The first thing is to run the test in isolation, and get a feel for whether
it's a consistent or sporadic failure.  Like so:

    python test.py -vvLd test_config testZEOStorage

The -L option makes it loop.  The -d option makes the loop stop if the test
fails.  I get output like this:

"""
Running unit tests at level 1
Running unit tests from C:\Code\Zope3
testZEOStorage (zodb.storage.tests.test_config.StorageTestCase) ... ok

----------------------------------------------------------------------
Ran 1 tests in 7.391s

OK
testZEOStorage (zodb.storage.tests.test_config.StorageTestCase) ... ok

----------------------------------------------------------------------
Ran 1 tests in 6.219s

OK
testZEOStorage (zodb.storage.tests.test_config.StorageTestCase) ... ok

----------------------------------------------------------------------
Ran 1 tests in 6.109s

OK
"""

and on & on -- it never fails for me (this is Python 2.2.2 under Win2K and
MSVC 6).


To get logging info, set the environment variable LOGGING to 0.  Then run
the test once:

    python test.py -vv test_config testZEOStorage

The logging output goes to your terminal, and I get surprisingly little of
it:

"""
Running unit tests at level 1
Running unit tests from C:\Code\Zope3
testZEOStorage (zodb.storage.tests.test_config.StorageTestCase) ...
WARNING:ZCS.720:ClientStorage (pid=720) created RW/normal for storage: '1'
WARNING:ZEC.1:ClientCache: storage='1', size=20971520; file[0]=None
INFO:root:zrpc:720: CM.connect(): starting ConnectThread
INFO:root:zrpc:720: CT: attempting to connect on 1 sockets
INFO:root:zrpc:720: CW: attempt to connect to ('www.python.org', 9001)
INFO:root:zrpc:720: CW: connect_ex(('www.python.org', 9001)) returned
WSAEWOULDBLOCK
INFO:root:zrpc:720: CT: select() 0, 0, 0
INFO:root:zrpc:720: CT: select() 0, 0, 1
INFO:root:zrpc:720: CT: closing troubled socket ('www.python.org', 9001)
INFO:root:zrpc:720: CM.close(): stopping and joining thread
INFO:root:zrpc:720: CT: exiting thread: Connect([(2, ('www.python.org',
9001))])

ok

----------------------------------------------------------------------
Ran 1 tests in 6.359s

OK
"""

Barry sez this logging output is expected -- we don't expect to find a ZEO
server on port 9001 at www.python.org, so the "closing troubled socket" log
msg is appropriate.  But if a bug in Cygwin select() causes this socket to
appear in both the w and x sets, then (see my first msg) a KeyError will
happen.  (I don't know whether that's happening, I'm only speculating based
on the most obvious thing that *could* be going wrong.)