Re: Re: closed connection during Zope2 request

Jim, thanks for your hint.

In a less elegant mode, I was doing exactly what you are suggesting to me:

this is my modified Connection.close:

    def close(self, primary=True):
        """Close the Connection."""
        ...
        # Call the close callbacks.
        ...
        self._debug_info = ()
+        # stack inspection ....
+        self.setDebugInfo(
+           "%s - close (opened %s) (primary %s %d)" %
+             (time.time(), self.opened, primary,
+             len(primary and self.connections.values() or [])))
+        self.setDebugInfo("%s" % traceback.format_stack())


and this is my modified logging exception (one of them)

    def setstate(self, obj):
        """Turns the ghost 'obj' into a real object by loading its state
from
        the database."""
        self.setDebugInfo("%s - setstate" % time.time())
        oid = obj._p_oid

        if self.opened is None:
            msg = ("Shouldn't load state for %s %s "
                   "when the connection is closed"
                   % (className(obj), oid_repr(oid)))
            try:
                raise ConnectionStateError(msg)
            except:
                self._log.exception(msg)
+              self._log.error("debugInfo %s", self.getDebugInfo())
                raise

and below the last part of the stack from three exceptions.

What looks weird is that apparently it suddenly calls the __del__ of the
ZApplication.Cleanup (1) instance that's on hold on the request (2),
therefore closing the ZODB connection (3).

...
File "/opt/cache/buildout/eggs/zope.tal-3.5.2-py2.7.egg/zope/tal/
talinterpreter.py",
line 182, in __init__
     self.program = program
File "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
line 84, in __del__
     self._jar.close()
File "/opt/cache/buildout/eggs/ZODB
3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
line 384, in close
     self.setDebugInfo("%s" % traceback.format_stack())

...
File "/opt/cache/buildout/eggs/Products.PlonePAS-5.0.9-py2.7.egg/
Products/PlonePAS/plugins/ufactory.py",
line 72, in _getPAS
     return self.acl_users
File "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
line 84, in __del__
     self._jar.close()
File "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.
egg/ZODB/Connection.py",
line 384, in close
     self.setDebugInfo("%s" % traceback.format_stack())

...
File "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/Products/
PageTemplates/Expressions.py",
line 88, in trustedBoboAwareZopeTraverse
     path_items = list(path_items)
File "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
line 84, in __del__
     self._jar.close()
File "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.
egg/ZODB/Connection.py",
line 384, in close
     self.setDebugInfo("%s" % traceback.format_stack())

from Zope2-2.13.23-py2.7.egg/App/ZApplication.py

class ZApplicationWrapper:
    ...
    def __bobo_traverse__(self, REQUEST=None, name=None):
        ...
        # arrange for the connection to be closed when the request goes away
        cleanup = Cleanup(conn)
(2)     REQUEST._hold(cleanup)
        ...

(1) class Cleanup:
    def __init__(self, jar):
        self._jar = jar

    def __del__(self):
        transaction.abort()
(3)     self._jar.close()




On Fri, Sep 30, 2016 at 2:22 PM Jim Fulton <[email protected]> wrote:

> Connections have close callbacks.  Maybe you can add a close callback
> that helps you debug where this is happening.  In your callback,
> you'll probably want to inspect the stack frame to filter out expected
> cases.
>
> Jim
>
> On Fri, Sep 30, 2016 at 8:02 AM, Mauro Amico <[email protected]>
> wrote:
> > Thanks Jens, I know the common case, but I think that we are not in a
> common
> > case.
> > Objects "disconnected" are everytime different and not correlated to a
> > custom package (that are very limited).
> > The stack trace below is making me crazy ... but probably there is
> nothing
> > strange on that, it's only something that I don't understand or that I
> don't
> > see ...
> >
> > Any other hints?
> >
> > Thx again,
> > Mauro.
> >
> > ...
> > File
> >
> "/opt/cache/buildout/eggs/zope.tal-3.5.2-py2.7.egg/zope/tal/talinterpreter.py",
> > line 182, in __init__
> >      self.program = program
> > File
> > "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
> > line 84, in __del__
> >      self._jar.close()
> > File
> >
> "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
> > line 384, in close
> >      self.setDebugInfo("%s" % traceback.format_stack())
> >
> > ----------------------------
> > ...
> > File
> >
> "/opt/cache/buildout/eggs/Products.PlonePAS-5.0.9-py2.7.egg/Products/PlonePAS/plugins/ufactory.py",
> > line 72, in _getPAS
> >      return self.acl_users
> > File
> > "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
> > line 84, in __del__
> >      self._jar.close()
> > File
> >
> "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
> > line 384, in close
> >      self.setDebugInfo("%s" % traceback.format_stack())
> >
> > ----------------------------
> > ...
> > File
> >
> "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/Products/PageTemplates/Expressions.py",
> > line 88, in trustedBoboAwareZopeTraverse
> >      path_items = list(path_items)
> > File
> > "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
> > line 84, in __del__
> >      self._jar.close()
> > File
> >
> "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
> > line 384, in close
> >
> >
> >
> > On Thu, Sep 29, 2016 at 10:26 PM, Jens W. Klein <[email protected]>
> > wrote:
> >>
> >> The most common case when this appears is when you set an persistent
> >> object to an non persistent which is bound (as part of a dict, list or
> >> attribute, ... or alike) to a global or a thread local variable and then
> >> survives the request/response cycle.
> >>
> >> Most commonly here it a wrong usage of caches or some kind of
> registries.
> >>
> >> Jens
> >>
> >> On 2016-09-29 18:43, Mauro Amico wrote:
> >> > Hi.
> >> >
> >> > We keep running into errors like "ZODB.Connection Shouldn't load state
> >> > for ...", but they don't seem to be due to the usual persistent
> objects
> >> > cached in ramcache
> >> > or similar, because we have those errors in several different
> situations
> >> > and on different installations with different custom packages.
> >> >
> >> > By analyzing on depth we noticed a weird behavior. It looks like the
> >> > connection is somehow closed in the middle of a request. We tried to
> get
> >> > more info saving the stack in the _debug_info of the connection with
> >> > traceback.format_stack() everytime the connection close happens, in
> >> > order to eventually print it in case of exception like
> "ZODB.Connection
> >> > Shouldn't load state for ..."
> >> >
> >> > Below you can find some lines of the stack traces that we get when we
> >> > run into the errors.
> >> > What looks weird to us is that apparently it suddenly calls the
> __del__
> >> > of a ZApplication.Cleanup instance that's on hold on the request,
> >> > therefore closing the ZODB connection.
> >> >
> >> > Any ideas about why this is happening or about what else we can
> >> > investigate on?
> >> >
> >> > Thanks in advance
> >> >
> >> > Mauro.
> >> >
> >> > ...
> >> > File
> >> >
> >> >
> "/opt/cache/buildout/eggs/zope.tal-3.5.2-py2.7.egg/zope/tal/talinterpreter.py",
> >> > line 182, in __init__
> >> >     self.program = program
> >> > File
> >> >
> "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
> >> > line 84, in __del__
> >> >     self._jar.close()
> >> > File
> >> >
> >> >
> "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
> >> > line 384, in close
> >> >     self.setDebugInfo("%s" % traceback.format_stack())
> >> >
> >> > ----------------------------
> >> >
> >> > ...
> >> > File
> >> >
> >> >
> "/opt/cache/buildout/eggs/Products.PlonePAS-5.0.9-py2.7.egg/Products/PlonePAS/plugins/ufactory.py",
> >> > line 72, in _getPAS
> >> >     return self.acl_users
> >> > File
> >> >
> "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
> >> > line 84, in __del__
> >> >     self._jar.close()
> >> > File
> >> >
> >> >
> "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
> >> > line 384, in close
> >> >     self.setDebugInfo("%s" % traceback.format_stack())
> >> >
> >> > ----------------------------
> >> >
> >> > ...
> >> > File
> >> >
> >> >
> "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/Products/PageTemplates/Expressions.py",
> >> > line 88, in trustedBoboAwareZopeTraverse
> >> >     path_items = list(path_items)
> >> > File
> >> >
> "/opt/cache/buildout/eggs/Zope2-2.13.23-py2.7.egg/App/ZApplication.py",
> >> > line 84, in __del__
> >> >     self._jar.close()
> >> > File
> >> >
> >> >
> "/opt/cache/buildout/eggs/ZODB3-3.10.5-py2.7-linux-x86_64.egg/ZODB/Connection.py",
> >> > line 384, in close
> >> >
> >>
> >>
> >> --
> >> Klein & Partner KG, member of BlueDynamics Alliance
> >>
> >> --
> >> You received this message because you are subscribed to the Google
> Groups
> >> "zodb" group.
> >> To unsubscribe from this group and stop receiving emails from it, send
> an
> >> email to [email protected].
> >> For more options, visit https://groups.google.com/d/optout.
> >
> >
> >
> >
> > --
> > Mauro
> >
> > --
> > You received this message because you are subscribed to the Google Groups
> > "zodb" group.
> > To unsubscribe from this group and stop receiving emails from it, send an
> > email to [email protected].
> > For more options, visit https://groups.google.com/d/optout.
>
>
>
> --
> Jim Fulton
> http://jimfulton.info
>

-- 
You received this message because you are subscribed to the Google Groups "zodb" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
For more options, visit https://groups.google.com/d/optout.