Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-25 Thread Chris Withers 

Dieter Maurer wrote:

-self._log.error(msg)
+self._log.error(msg,exc_info=True)
raise ConnectionStateError(msg)


I mind -- the change is stupid:

  Because you are not in an exception handler, "exc_info=True"
  cannot provide meaningful information -- there is no
  exception that can be presented...


Yes, true *sigh*

I guess I'm looking for a show_stack option...

Tim, how would I go about getting one of those added to Python?
(It's not much of a code change, but the process of getting it into 
python seems a bit daunting from an outsiders perspective...)


cheers,

Chris

--
Simplistix - Content Management, Zope & Python Consulting
   - http://www.simplistix.co.uk
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

RE: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-21 Thread Tim Peters 
[Tim]
...
>> BTW, I haven't seen a traceback associated with your "shouldn't load
>> state" problems.  Do any exist?  (I understand they may not be logged,
>> I'm wondering if you can see them from the ZMI.  If it _is_
>> unintentional caching, a traceback could be invaluable.)

[Chris Withers]
> I agree.

Did you do the Google exercise I suggested :-)?  What I found when I did it
is that other people with "cannot load state" problems sometimes found the
answer by looking at a traceback in the ZMI, and then just noting which app
code was doing the load.  It wasn't always that easy, but sometimes it
pointed at exactly the app code responsible for holding on to an old object.

> Do you mind if I apply the following patch to the ZODB trunk?
>
> Index: Connection.py
> === ---
> Connection.py   (revision 39510) +++ Connection.py   (working
> copy) @@ -725,7 +725,7 @@
>   if self._opened is None:
>   msg = ("Shouldn't load state for %s "
>  "when the connection is closed" % oid_repr(oid))
> - self._log.error(msg)
> + self._log.error(msg,exc_info=True)
>   raise ConnectionStateError(msg)

As Dieter already said (thanks, Dieter!), this change doesn't make sense.  I
understand that you want to see a traceback, but the traceback you want
doesn't exist before the "raise ConnectionStateError(msg)" on the following
line executes.  App code has to log that; it's "too early" here.

>   try:
> @@ -734,7 +734,7 @@
>   raise
>   except:
>   self._log.error("Couldn't load state for %s", oid_repr(oid),
> - exc_info=sys.exc_info())
> + exc_info=True)
>   raise
>
>   def _setstate(self, obj):
>
> (the second bit should happen anyway ;-) )

This one is fine.  It doesn't make much difference ("True" and
"sys.exc_info()" _mean_ the same thing in this context), but I like the
"True" spelling better too.

Note that if you changed both instances of exc_info=sys.exc_info() in this
module, it could lose the "import sys" near the top too.  Clean code just
gets cleaner & cleaner ;-)

> Once this is done, how does it wend its way into a Zope 2.8 release?

At some point I'll make a new tag from then-current ZODB 3.4 branch and
change Zope's 2.8 branch to use that new tag.  I usually do that only when a
Zope release is looming, or an important ZODB bugfix gets made.

> What other branches / changes.txt files should I merge to?

ZODB/branches/3.4
ZODB/branches/3.5
ZODB/trunk

If possible, the change should be made in 3.4 first, and then merged from
there to the 3.5 branch and trunk.  I wouldn't change NEWS.txt on any of
them for this, since it's purely internal cleanup with (one hopes) no
visible consequence.


___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-21 Thread Dieter Maurer 
Chris Withers wrote at 2005-10-21 15:28 +0100:
> ...
>Do you mind if I apply the following patch to the ZODB trunk?
>
>Index: Connection.py
>===
>--- Connection.py   (revision 39510)
>+++ Connection.py   (working copy)
>@@ -725,7 +725,7 @@
>  if self._opened is None:
>  msg = ("Shouldn't load state for %s "
> "when the connection is closed" % oid_repr(oid))
>-self._log.error(msg)
>+self._log.error(msg,exc_info=True)
>  raise ConnectionStateError(msg)

I mind -- the change is stupid:

  Because you are not in an exception handler, "exc_info=True"
  cannot provide meaningful information -- there is no
  exception that can be presented...

>
>  try:
>@@ -734,7 +734,7 @@
>  raise
>  except:
>  self._log.error("Couldn't load state for %s", oid_repr(oid),
>-exc_info=sys.exc_info())
>+exc_info=True)

I do not mind this change.


-- 
Dieter
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-21 Thread Chris Withers 

Tim Peters wrote:


If a client restarted during the day, wouldn't you find evidence of that in
your logs?


Yep...


This is all there is to it, where Data.fs has a single large OOBTree
attached as to the root under key "tree":



st = ZODB.FileStorage.FileStorage('Data.fs')
db = ZODB.DB(st)
cn = db.open()
rt = cn.root()
tree = rt['tree']
type(tree)





cn.close()  # DON'T BLINK
tree[20]


Yep, I understand the mechanics, just not where it's happening ;-)


BTW, because we didn't see ConnectionStateError at the time cn.close() was
done, we know that no objects loaded from the Connection were left in a
modified state.  


That sounds like a good thing :-)


BTW, I haven't seen a traceback associated with your "shouldn't load state"
problems.  Do any exist?  (I understand they may not be logged, I'm
wondering if you can see them from the ZMI.  If it _is_ unintentional
caching, a traceback could be invaluable.)


I agree.

Do you mind if I apply the following patch to the ZODB trunk?

Index: Connection.py
===
--- Connection.py   (revision 39510)
+++ Connection.py   (working copy)
@@ -725,7 +725,7 @@
 if self._opened is None:
 msg = ("Shouldn't load state for %s "
"when the connection is closed" % oid_repr(oid))
-self._log.error(msg)
+self._log.error(msg,exc_info=True)
 raise ConnectionStateError(msg)

 try:
@@ -734,7 +734,7 @@
 raise
 except:
 self._log.error("Couldn't load state for %s", oid_repr(oid),
-exc_info=sys.exc_info())
+exc_info=True)
 raise

 def _setstate(self, obj):

(the second bit should happen anyway ;-) )

Once this is done, how does it wend its way into a Zope 2.8 release?
What other branches / changes.txt files should I merge to?

cheers,

Chris

--
Simplistix - Content Management, Zope & Python Consulting
   - http://www.simplistix.co.uk
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

RE: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-20 Thread Tim Peters 
[Chris Withers]
> ...
> Hmm.. well, I guess the clients could have restarted during the day and
> so maybe it is a startup race?

If a client restarted during the day, wouldn't you find evidence of that in
your logs?

...

 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.

> Hurm... Zope? Plone? Sessions? Which one shall it be today? *sigh* Any
> clues greatfully received (ie: common patterns that cause this error)

Try Google.

Unintentional, or flawed intentional, app caching is a good candidate.  I've
only tracked down one of these in my life, which turned out to be
unintentional caching (a non-persistent class instance unintentionally
holding on to a persistent object across requests).

This is all there is to it, where Data.fs has a single large OOBTree
attached as to the root under key "tree":

>>> st = ZODB.FileStorage.FileStorage('Data.fs')
>>> db = ZODB.DB(st)
>>> cn = db.open()
>>> rt = cn.root()
>>> tree = rt['tree']
>>> type(tree)

>>> cn.close()  # DON'T BLINK
>>> tree[20]
Traceback (most recent call last):
  File "", line 1, in ?
  File "ZODB\Connection.py", line 587, in setstate
raise RuntimeError(msg)
RuntimeError: Shouldn't load state for 0x01 when the connection is closed

Is that clear?  `tree` there got loaded from a connection, the connection
got closed, and _then_ code tried to access state reachable from `tree`.
Well, it can't:  the connection is no longer open to load the state from, so
Connection complains.

BTW, because we didn't see ConnectionStateError at the time cn.close() was
done, we know that no objects loaded from the Connection were left in a
modified state.  This is what happens if an app tries to do that:

>>> st = ZODB.FileStorage.FileStorage('Data.fs')
>>> db = ZODB.DB(st)
>>> cn = db.open()
>>> rt = cn.root()
>>> tree = rt['tree']
>>> tree[20]
20
>>> tree[20] = 40  # modify an object
>>> cn.close() # then try to close the connection w/o commit or abort
Traceback (most recent call last):
  File "", line 1, in ?
  File "ZODB\Connection.py", line 306, in close
raise ConnectionStateError("Cannot close a connection joined to "
ZODB.POSException.ConnectionStateError: Cannot close a connection joined to
a transaction

Of course it's possible that some app code you're using suppresses
ConnectionStateError too.  If not, "unintentional caching" is a good bet.

BTW, I haven't seen a traceback associated with your "shouldn't load state"
problems.  Do any exist?  (I understand they may not be logged, I'm
wondering if you can see them from the ZMI.  If it _is_ unintentional
caching, a traceback could be invaluable.)


___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

RE: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-20 Thread Tim Peters 
[Chris Withers]
>>> First question, would you mind if I added oid_unrepr to ZODB.utils? I

[Dieter Maurer]
>> Why do you not like "p64" (which is already there)?

[Chris]
> If that's the case, then great :-)
>
> I was just asking 'cos I couldn't find he functionality anywhere,

You found ZODB.utils, which was a sensible place to look.  I don't really
understand how you found ZODB.utils but didn't manage to find p64, because
p64 is the first function in the file.

> I guess p64 needs documenting,

I think its docstring is reasonably clear:

def p64(v):
"""Pack an integer or long into a 8-byte string"""

In addition to that, it would be helpful to have a tutorial overview
"somewhere" explaining that FileStorage oids are 8-byte strings.  I don't
know where to put that so that people would find it, though.  For example,
where would you have found it?

> and maybe a better name?

Many ZODB users already know this, and there are references to p64 on user
web pages.  For example,

http://www.zopezone.com/discussions/general/0168

shows how to do what you started out to do:

>>> from Zope.Startup.run import configure;configure('zope-8000/zope.conf')
>>> from Zope import app; root = app()
>>> from ZODB.utils import p64
>>> o = root._p_jar[p64(0x277FEL)]
>>> o
OOBucket([('566', -1920968609), ...])

I don't want to break pages like that, so the current name has to remain.
It would be possible to add an alias.  I'm -0 on that (would violate TOOWTDI
in exchange for ... well, not sure it would really help anyone anyway).


___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-20 Thread Chris Withers 

Dieter Maurer wrote:

First question, would you mind if I added oid_unrepr to ZODB.utils? I 


Why do you not like "p64" (which is already there)?

p64(0x)

behaves very similar to

oid_unrepr('0x')


If that's the case, then great :-)

I was just asking 'cos I couldn't find he functionality anywhere, I 
guess p64 needs documenting, and maybe a better name?


Chris

--
Simplistix - Content Management, Zope & Python Consulting
   - http://www.simplistix.co.uk
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-19 Thread Dieter Maurer 
Chris Withers wrote at 2005-10-19 13:53 +0100:
> ...
>from binascii import unhexlify
>def oid_unrepr(oidr):
> if oidr.startswith('0x'):
> oidr = oidr[2:]
> h = unhexlify(oidr)
> return '\x00'*(8-len(h))+h
>
>def oidr2obj(app,oidr):
> return app._p_jar[oid_unrepr(oidr)]
>
>First question, would you mind if I added oid_unrepr to ZODB.utils? I 

Why do you not like "p64" (which is already there)?

p64(0x)

behaves very similar to

oid_unrepr('0x')



>- http://www.simplistix.co.uk
>

-- 
Dieter
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-19 Thread Chris Withers 

Hi Tim,

Tim Peters wrote:

As before, this "Shouldn't load state ..." error is almost certainly due to
a logic error in some product you're using, or in Zope.  Take this message
as meaning exactly what it says:  something is trying to work with a
persistent object after the Connection it came from was closed.  That's an
app problem, not a ZODB problem.  Have you tracked down what kind of object
(say) oid 0x6c33b4 is?  That may give a good clue.


Okay, had a spat of 6 of these in the same minute (significant?), with 
no particular known trigger, on one of the machines in a cluster this 
morning, so I went digging.


I started by writing two little methods for use in a zopectl debug session:

from binascii import unhexlify
def oid_unrepr(oidr):
if oidr.startswith('0x'):
oidr = oidr[2:]
h = unhexlify(oidr)
return '\x00'*(8-len(h))+h

def oidr2obj(app,oidr):
return app._p_jar[oid_unrepr(oidr)]

First question, would you mind if I added oid_unrepr to ZODB.utils? I 
couldn't find this anywhere, and it's kinda handy to have ;-)


Anyway, armed with my little friends, I went digging for the types of 
the oids causing problems.
For kicks, I started off with 0x6c33b4 that you mention above. Doing the 
following in a zopectl debug session gave:


>>>obj = oidr2obj(app,'0x6c33b4')
>> obj


...which is just an AT-based Plone content object.

Okay, now the 6 from today:

>> oidr2obj(app,'0x66b0ad')



...upon digging further, this was the OOBTree that stores the contents 
of one of our CMFBTreeFolder2. Two identical errors for this occurred 
straight after each other on the server in question.


The rest were all roughly the same, and shortly followed the error for 
0x66b0ad:


>> obj = oidr2obj(app,'0xab653f')
ZODB.POSException.POSKeyError: 0xab653f
>> obj = oidr2obj(app,'0xab4e40')
ZODB.POSException.POSKeyError: 0xab4e40
>> obj = oidr2obj(app,'0xab653f')
ZODB.POSException.POSKeyError: 0xab653f
>> obj = oidr2obj(app,'0xab4e40')
ZODB.POSException.POSKeyError: 0xab4e40

Now, my guess, and I do mean guess, is that maybe these were objects in 
the TemporaryStorage that we serve over ZEO to back the session data 
container...


However, other than documenting what I've found, and maybe adding a 
little microutility to ZODB.utils, I haven't really gotten anywhere :-(


Any ideas?

Chris

--
Simplistix - Content Management, Zope & Python Consulting
   - http://www.simplistix.co.uk
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-18 Thread Chris Withers 

Hi Tim,

Thanks for the feedback,


[Chris]


AttributeError: ClientCache instance has no attribute '_get'
Both at random times while the servers are running...


Tim Peters wrote:

Then-- sorry --I don't have a clue.  Like I said, I don't see any code
capable of removing a ClientCache's `_get` attribute after the cache has
been opened, and I don't see a way for a ZEO client cache to work at all
without its _get attribute (_get is used on every load and every
invalidate).  If this only occurred at client startup time, then it might
get pinned on a startup race.  But if it occurs at random times while the
servers are running, I have no theory.


Hmm.. well, I guess the clients could have restarted during the day and 
so maybe it is a startup race?



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?


Up to you, but you should know I gave up .  


No one needs covering in pink squishy bits this close to Christmas...


The log shows that your client takes the "full cache verification" path.  We
know this because it says, e.g.,

2005-10-11T17:57:58 INFO(0) ZCS:13033 Verifying cache

and "Verifying cache" is produced from only one place in ZODB.  That's this
block in ClientStorage.verify_cache:

log2(INFO, "Verifying cache")
# setup tempfile to hold zeoVerify results
self._tfile = tempfile.TemporaryFile(suffix=".inv")
self._pickler = cPickle.Pickler(self._tfile, 1)
self._pickler.fast = 1 # Don't use the memo

self._cache.verify(server.zeoVerify)
self._pending_server = server
server.endZeoVerify()
return "full verification"


Note that this calls self._cache.verify(), and that's exactly the verify()
method I talked about just above (the one that opens the cache immediately,
giving the cache its _get attribute).


Rats.


I suppose it's _conceivable_ that there's some obscure race allowing a load
or invalidation attempt to sneak in here, before self._cache.verify() is
called.  But if so, that's necessarily part of ZEO client startup, you say
it's not correlated with startup, and your logs don't show anything unusual
between "Verifying cache" and "endVerify finishing".


More rats. There some sinking ship knocking around here?


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.


Hurm... Zope? Plone? Sessions? Which one shall it be today? *sigh*
Any clues greatfully received (ie: common patterns that cause this error)


app problem, not a ZODB problem.  Have you tracked down what kind of object
(say) oid 0x6c33b4 is?  That may give a good clue.


Indeed, next time I see one, I'll have a poke. Dont suppose you have a 
snippet to have to turn 0x6c33b4 into a python object using a zopectl 
debug session?



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


ZODB raises ReadConflictError specifically for a read conflict.  It raises
ConflictError for a write conflict.  Whatever code in Zope produces the log
messages apparently suppresses the distinction.  This is easy to do, since
ReadConflictError is a subclass of ConflictError; I _guess_ that code just
catches the base ConflictError to capture both.  Poking around in Zope might
help (maybe there's an easy way to change it to preserve the distinction).


Shall do!

thanks for all the help,

cheers,

Chris

--
Simplistix - Content Management, Zope & Python Consulting
   - http://www.simplistix.co.uk
___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev

RE: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-17 Thread Tim Peters 
[Chris Withers]
>>> 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:

...

>>> AttributeError: ClientCache instance has no attribute '_get'

[Tim Peters]
>> 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?

[Chris]
> Both at random times while the servers are running...

Then-- sorry --I don't have a clue.  Like I said, I don't see any code
capable of removing a ClientCache's `_get` attribute after the cache has
been opened, and I don't see a way for a ZEO client cache to work at all
without its _get attribute (_get is used on every load and every
invalidate).  If this only occurred at client startup time, then it might
get pinned on a startup race.  But if it occurs at random times while the
servers are running, I have no theory.

...

>> 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...

I doubt it's related to your

Shouldn't load state for 0x660bab when the connection is closed

problems except by coincidence.

>> 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?

Up to you, but you should know I gave up .  If you do, you'll
eventually figure out that there's a wide-open path in ClientStorage.py that
never calls:

self._cache.open()

I got hopeful at that point, but turns out it's a red herring.  If you look
at ClientCache.py's ClientCache.verify(), you'll see that it unconditionally
calls self.open() (which is the same thing).  So there's no way to call
ClientCache.verify() without open()'ing the client cache as a side effect.

>> 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)

The log shows that your client takes the "full cache verification" path.  We
know this because it says, e.g.,

2005-10-11T17:57:58 INFO(0) ZCS:13033 Verifying cache

and "Verifying cache" is produced from only one place in ZODB.  That's this
block in ClientStorage.verify_cache:

log2(INFO, "Verifying cache")
# setup tempfile to hold zeoVerify results
self._tfile = tempfile.TemporaryFile(suffix=".inv")
self._pickler = cPickle.Pickler(self._tfile, 1)
self._pickler.fast = 1 # Don't use the memo

self._cache.verify(server.zeoVerify)
self._pending_server = server
server.endZeoVerify()
return "full verification"


Note that this calls self._cache.verify(), and that's exactly the verify()
method I talked about just above (the one that opens the cache immediately,
giving the cache its _get attribute).

I suppose it's _conceivable_ that there's some obscure race allowing a load
or invalidation attempt to sneak in here, before self._cache.verify() is
called.  But if so, that's necessarily part of ZEO client startup, you say
it's not correlated with startup, and your logs don't show anything unusual
between "Verifying cache" and "endVerify finishing".

>>> 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?

I don't think so.

> (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?)

setstate() doesn't _create_ an object, it just adds state to a ghost object
that already exists.  A ghost first comes into being when some other
persistent object is loaded, which contains the ghost object.  The newly
created ghost object is then associated with the Connection used to load the
containing persistent object.  It remains a ghost until something references
one of its attributes, and only then does setstate() get called on it.

IOW, for a ghost to exist and be associated with a Connection at all

Re: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-12 Thread 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=2; file[0]='main-None-0'
--
2005-10-11T17:57:58 INFO(0) ZCS:13033 Testing connection

--
2005-10-11T17:57:58 INFO(0) zrpc-conn(C):x.x.x.x: 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

--
2005-10-11T17:57:58 INFO(0) zrpc-conn(C):x.x.x.x: 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',
)
--
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 ER

RE: [ZODB-Dev] Weird errors with Zope 2.7.7

2005-10-11 Thread Tim Peters 
[Chris Withers]
> 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?

> ERROR(200) zrpc-conn(C):x.x.x.x: Asynchronous call raised exception:
>  Traceback (most recent call
last):
>File "lib/python/ZEO/zrpc/connection.py",
> line 373, in handle_request
>  ret = meth(*args)
>File "/lib/python/ZEO/ClientStorage.py",
> line , in invalidateTransaction
>  self._process_invalidations(args)
>File "lib/python/ZEO/ClientStorage.py",
> line 1074, in _process_invalidations
>  self._cache.invalidate(oid, version=version)
>File "lib/python/ZEO/ClientCache.py",
> line 297, in invalidate
>  p = self._get(oid, None)
> AttributeError: ClientCache instance has no attribute '_get'
>
> ...which seems a little odd :-S

Peculiar:  in 2002, you called it "weird" instead ;-):

http://mail.zope.org/pipermail/zodb-dev/2002-December/004091.html

[Chris Withers]
[...]
AttributeError: ClientCache instance has no attribute '_get'

...which is weird :-S

[...]

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.

It looks like open() is "supposed to be" called sometime during initial
cache verification.  That code is complicated.  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.

> 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.  It's far more likely that this one is a bug in
Zope or some product than that it's a bug in ZODB (ZODB simply doesn't _try_
to load objects unless an app tells it to; ditto for opening or closing
connections).

> This is on a ZEO setup with the storage server running a FileStorage and
> a TemporaryStorage on Slowlartis (changing this evening, don't worry!)
> and multiple ZEO clients each running on their own linux box.
>
> Has anyone seen any of the above with 2.7.7?

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.


___
For more information about ZODB, see the ZODB Wiki:
http://www.zope.org/Wikis/ZODB/

ZODB-Dev mailing list  -  ZODB-Dev@zope.org
http://mail.zope.org/mailman/listinfo/zodb-dev