[ZODB-Dev] Weird errors with Zope 2.7.7

[Chris Withers]

Hey Tim :-)

Tim Peters wrote:
>>We've been seeing these errors for a while now, but had assumed it was
>>due to an old Zope version. We've been running 2.7.7 for a week or two
>>now and we're still seeing these intermittently:
> 
> At any particular time(s)?  For example, do these (either or both) tend to
> occur when a ZEO client is starting up?  Shutting down?  In the middle of
> their lives?  No correlation?

Both at random times while the servers are running...

>>AttributeError: ClientCache instance has no attribute '_get'
>>
>>...which seems a little odd :-S
> 
> Peculiar:  in 2002, you called it "weird" instead ;-):

Weird, peculiar, odd, fubared ;-)

>     http://mail.zope.org/pipermail/zodb-dev/2002-December/004091.html
> 
>     [Chris Withers]
>     [...]
>     AttributeError: ClientCache instance has no attribute '_get'
> 
>     ...which is weird :-S

Maybe I'm just a bot!

> A ClientCache doesn't have a `_get` attribute when it's first constructed;
> for whatever reason, it doesn't get one until ClientCache.open() is called.
> I don't see any code capable of removing the `_get` attribute from a
> ClientCache after its open() is called, so looks like a safe bet its open()
> has never been called.

Now that _is_ weird, especially given the other error below...

> It looks like open() is "supposed to be" called sometime during initial
> cache verification.  That code is complicated. 

Hmmm, Tim says the code is complicated, I guess I should be prepared to
wipe my brains off the wall should I try and read it?

> It would help to have more
> of the log context, especially the INFO-level log messages produced by this
> ZEO client during startup:  this could be a ZEO startup race, but there are
> so many possible paths thru that code that more clues are needed.

*goes hunting* (will include at end of mail)

>>ERROR(200) ZODB Shouldn't load state for 0x6c33b4 when the connection is
> 
> closed
> 
>>...which is a bit more distrubing.
> 
> That one comes out of Connection.setstate(), and appears to mean what it
> says:  the app is trying to load an object from this Connection but the
> Connection has been closed.

Right, could this be related to the _get error?
(ie: if _get only gets created when the connection is opened, and it's
not there, then maybe the connection (which connection?!) has never been
opened and so barfs with the "shouldn't load state" error when something
tries to load an object from it?)

> I haven't seen other reports; the only Google hits on the ClientCache
> AttributeError are in messages from you, so that one can't be widespread.

I must be cursed :-(

Anyway, here's the logs... this zeo client has poped up a few "shouldn't 
load states" but no "where's my _get"'s, yet...

------
2005-10-11T17:57:58 INFO(0) ZCS:13033 ClientStorage (pid=13033) created
RW/normal for storage: 'main'
------
2005-10-11T17:57:58 INFO(0) ZEC:main-None-0 ClientCache: storage='main',
size=200000000; file[0]='main-None-0'
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Testing connection
<ManagedClientConnection ('x.x.x.x', yyyy)>
------
2005-10-11T17:57:58 INFO(0) zrpc-conn(C):x.x.x.x:yyyy received
handshake 'Z201'
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Server authentication protocol None
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Verifying cache
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Waiting for cache verification to
finish
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Waiting for cache verification to
finish
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 endVerify finishing
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 endVerify finished
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 ClientStorage (pid=13033) created
RW/normal for storage: 'temp'
------
2005-10-11T17:57:58 INFO(0) ZEC:temp-None-0 ClientCache: storage='temp',
size=20971520; file[0]='temp-None-0'
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Testing connection
<ManagedClientConnection ('x.x.x.x', yyyy)>
------
2005-10-11T17:57:58 INFO(0) zrpc-conn(C):x.x.x.x:yyyy received
handshake 'Z201'
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Server authentication protocol None
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Connected to storage: ('zeo',
yyyy)
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Verifying cache
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Waiting for cache verification to
finish
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 Waiting for cache verification to
finish
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 endVerify finishing
------
2005-10-11T17:57:58 INFO(0) ZCS:13033 endVerify finished
------
2005-10-12T09:15:32 INFO(0) ZODB conflict error at
/VirtualHostBase/http/a_url
(15 conflicts since startup at 2005-10-11T17:58:00)
------
2005-10-12T09:15:38 INFO(0) ZODB conflict error at
/VirtualHostBase/http/b_url
(16 conflicts since startup at 2005-10-11T17:58:00)
------
2005-10-12T09:15:39 INFO(0) ZODB conflict error at
/VirtualHostBase/http/c_url (17 conflicts since startup at 
2005-10-11T17:58:00)
------
2005-10-12T09:15:43 INFO(0) ZODB conflict error at
/VirtualHostBase/http/a_url \
(18 conflicts since startup at 2005-10-11T17:58:00)
------
2005-10-12T09:15:43 ERROR(200) ZODB Shouldn't load state for 0x9aaa86 
when the connection is closed
------
2005-10-12T09:15:48 ERROR(200) ZODB Shouldn't load state for 0x9aaa86 
when the connection is closed
------
2005-10-12T09:15:48 ERROR(200) ZODB Shouldn't load state for 0x660bab 
when the connection is closed
------

(ps: this is only a few snippets stuck together, I figured you didn't 
really want the whole damn log ;-) )

(pps: kinda interested what those conflict errors are, read or write? 
how do I find out?)

cheers,

Chris

-- 
Simplistix - Content Management, Zope & Python Consulting
            - http://www.simplistix.co.uk