[ZCM] [ZC] 2293/ 6 Wontfix "ZEO: storage error occurred during the second phase of the two-phase commit"

Issue #2293 Update (Wontfix) "ZEO: storage error occurred during the second phase of the two-phase commit"
 Status Wontfix, Zope/bug medium
To followup, visit:
  http://www.zope.org/Collectors/Zope/2293

==============================================================
= Wontfix - Entry #6 by tseaver on Apr 25, 2007 11:47 am

 Status: Pending => Wontfix

Having looked at what 'five:registerPackage' is actually
doing, I'm marking this as 'WONTFIX':

  - I believe that the directive itself is misconceived:  it
    tries to make non-Zope2-aware packages function as though
    they were Zope2 products, which is not even desirable.
    The point of using packages rather than Products is to
    *avoid* having them conform to the dance Zope imposes on
    products:  this directive goes directly against that goal.

    The major goal of the directive appears to be to get the
    pseudo-product to show up in the Control_Panel's Products
    list:  that is the reason for committing the transaction.

  - The implementation of the directive *opens a new database
    connection* during Zope startup, which is the source of
    this bug:  Five itself is in the process of being initialized,
    and 

  - I have a nasty hack on hand which causes the
    directive to re-use the connection passed in to Five
    (as part of its ProductConfig), but I won't commit that
    hack into the Zope code to fix an "annoyance" in a feature
    which itself is already a hack.
________________________________________
= Comment - Entry #5 by tseaver on Apr 25, 2007 11:08 am


Uploaded:  "issue_2293.tar.gz"
 - http://www.zope.org/Collectors/Zope/2293/issue_2293.tar.gz/view
OK, the 'zeo.log' in your tarball shows an expected POSKeyError;
the database has never been opened, and so does not yet have
the root object (key 0x00).

The traceback occurs while in the middle of
fiveconfigure._registerPackage, which ssems to be doing a
spurious 'commit'.

(later) I've got a reproducible recipe now:

 1. Make a new Zope / ZEO instance::

    $ cd ~/projecte/Zope-CVS/Zope-2.10-branch
    $ bin/mkzeoinstance.py /tmp/issue_2293 9999
    $ bin/mkzopeinstance.py -d /tmp/issue_2293 admin:123

 2. Edit the 'etc/zope.conf' in the new instance to point to
    the ZEO server::

    $ cd /tmp/issue_2293
    $ vim etc/zope.conf

 3. Unpack the attached tarball, containing a single near-empty
    instance-local package and the configuration stub for it::

    $ tar xzf /tmp/issue_2293.tar.gz
    $ cat etc/package-includes/foobar-configure.zcml 
    <configure
        xmlns="http://namespaces.zope.org/zope">
      <include package="foobar" />
    </configure>
    $ cat lib/python/foobar/__init__.py
    def initialize(context):
        pass
    $ cat lib/python/foobar/configure.zcml 
    <configure
        xmlns="http://namespaces.zope.org/zope"
        xmlns:five="http://namespaces.zope.org/five"
        >
    
      <five:registerPackage
        package="."
        initialize=".initialize"
        />
    
    </configure>

 4. Start the ZEO server::

    $ bin/zeoctl start

 5. Run Zope in the foreground::

    $ bin/zopectl fg

On the first attempt, this recipe does provoke the assertion
error while handling the 'five:registerPackage' directive.

________________________________________
= Comment - Entry #4 by smcmahon on Apr 24, 2007 9:49 pm

A bit more information. The problem still exists with Zope 2.10.3, and occurs with Plone 3.0-beta-1 as well as the earlier alpha.

I've now reproduced it in every environment I've tested in, including:

- Ubuntu 6.10 Server
- FreeBSD 6.1
- Solaris 10
- Fedora Core 6
- Mac OS X 10.4

________________________________________
= Comment - Entry #3 by smcmahon on Mar 21, 2007 12:53 pm


Uploaded:  "logs.tgz"
 - http://www.zope.org/Collectors/Zope/2293/logs.tgz/view
I certainly understand why you wouldn't want to deal with the Plone 3.0 development stack. The problem is reproducible with the Plone 3.0-alpha-2 release (available at http://plone.org/products/plone/releases/3.0) if that's any help.

Attached is a .tgz archive containing the complete zeo and event logs for an error episode.
________________________________________
= Comment - Entry #2 by tseaver on Mar 20, 2007 8:37 pm

What is Plone doing during product init that would cause writes,
beyond those which the "stock" control panel does?  We will need
a reproducible testcase which shows this happening without needing
to install the development version of the Plone 3 stack.

For starters, please upload the compolete event log file from the
instance: your trimmed down version is too trimmed to tell us much.
Perhaps the information there will help us narrow the search.

________________________________________
= Request - Entry #1 by smcmahon on Mar 20, 2007 5:06 pm

In a ZEO configuration, when starting a client for the first time -- with no Data.fs in place -- with Plone 3.0 Alpha-2 in the instance Products and instance lib/python, during the plone package inits, an error will occur:

...
  from zope.app.event.objectevent import ObjectEvent
2007-03-20 12:47:24 INFO Plone OpenID packages not installed
2007-03-20 12:47:26 CRITICAL txn.-1210956112 A storage error occurred during the second phase of the two-phase commit.  Resources may be in an inconsistent state.
...

Five then fails to load.

This error does not occur if the Plone 3 Products and packages are not present. Nor does is occur in a stand-alone Zope configuration (i.e., no ZEO).

Restarting the client reliably clears the problem.

Problem reproduced on Ubuntu 6.10, FreeBSD 6.1 and Solaris 10.

==============================================================