ValueError: database_name 'share' already in databases

[Maik Derstappen]

If i start my zope2.10 instance in forground, i see this trace sometimes:

./bin/instance fg
/home/maik/development/zope/buildouts/share/sat/parts/instance/bin/runzope -X debug-mode=on
2009-07-09 13:23:51 INFO ZServer HTTP server started at Thu Jul 9 13:23:51 2009
 Hostname: 0.0.0.0
 Port: 8088
2009-07-09 13:23:53 INFO Marshall libxml2-python not available. Unable to register libxml2 based marshallers.
/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/zope/configuration/xmlconfig.py:323: DeprecationWarning: zope.app.annotation has moved to zope.annotation. Import of zope.app.annotation will become unsupported in Zope 3.5
  __import__(arguments[0])
2009-07-09 13:24:02 INFO Zope Ready to handle requests
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) ClientStorage (pid=20251) created RW/normal for storage: 'share'
2009-07-09 13:24:02 INFO ZEO.cache created temporary cache file '<fdopen>'
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Testing connection <ManagedClientConnection ('127.0.0.1', 8200)>
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) ClientStorage (pid=20251) created RW/normal for storage: 'share'
2009-07-09 13:24:02 INFO ZEO.zrpc.Connection(C) (127.0.0.1:8200) received handshake 'Z303'
2009-07-09 13:24:02 INFO ZEO.cache created temporary cache file '<fdopen>'
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Testing connection <ManagedClientConnection ('127.0.0.1', 8200)>
2009-07-09 13:24:02 INFO ZEO.zrpc.Connection(C) (127.0.0.1:8200) received handshake 'Z303'
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Server authentication protocol None
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Connected to storage: ('localhost', 8200)
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Verifying cache
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) endVerify finishing
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) endVerify finished
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Server authentication protocol None
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Connected to storage: ('localhost', 8200)
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Verifying cache
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) endVerify finishing
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) endVerify finished
2009-07-09 13:24:02 INFO ZEO.ClientStorage (20251) Disconnected from storage: "('localhost', 8200)"
2009-07-09 13:24:02 ERROR Zope.ZODBMountPoint Failed to mount database. exceptions.ValueError (database_name 'share' already in databases)
Traceback (most recent call last):
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/Products/ZODBMountPoint/MountedObject.py", line 257, in _getOrOpenObject
    conn = self._getMountedConnection(anyjar)
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/Products/ZODBMountPoint/MountedObject.py", line 147, in _getMountedConnection
    self._getDB()
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/Products/ZODBMountPoint/MountedObject.py", line 157, in _getDB
    return getConfiguration().getDatabase(self._path)
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/Zope2/Startup/datatypes.py", line 280, in getDatabase
    db = factory.open(name, self.databases)
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/Zope2/Startup/datatypes.py", line 178, in open
    DB = self.createDB(database_name, databases)
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/Zope2/Startup/datatypes.py", line 175, in createDB
    return ZODBDatabase.open(self, databases)
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/ZODB/config.py", line 105, in open
    databases=databases)
  File "/home/maik/development/zope/buildouts/share/sat/parts/zope2/lib/python/ZODB/DB.py", line 270, in __init__
    raise ValueError("database_name %r already in databases" %
ValueError: database_name 'share' already in databases

'share' is a ZODB Mountpoint which comes from a ZEO Server.
The Mountpoint is an ATFolder inside a Plone 3.2.2 Site.

[Jim Fulton (jim-zope)]

This looks like a plone bug. The error indicates that databases with the same name are being configured more than once.

[Christian Theune (ctheune)]

Maik talked to me on IRC and I got curious because there's a disconnect before it fails. He pointed out that it only fails when the disconnect happens.

[Dieter Maurer (d.maurer)]

It may also be related to a race condition (I expect this): two requests try to mount the same database at almost the same time:
both find the db missing in "self.databases" in "Zope2.Startup.datatypes.DBTAB.getDatabase" but the one trailing finds
it already added in "ZODB.DB.DB.__init__". Locking could prevent such race conditions.

[Jean Jordaan (jean-jordaan)]

This is biting me almost every time I startup a Zope instance with Plone sites in mounted storages. Don't know if it's relevant, but the filesystem on this box is quite slow.

Here are relevant bits from the log. Zope 2.9.9.

2010-01-27T05:11:04 INFO ZServer HTTP server started at Wed Jan 27 05:11:04 2010
 Hostname: 0.0.0.0
 Port: 12101
------
2010-01-27T05:11:04 INFO ZServer ICP server started
 Address: 0.0.0.0
 Port: 7102
------
[...]
2010-01-27T05:11:33 INFO Zope Ready to handle requests
------
2010-01-27T05:11:33 INFO ZODB.lock_file locked <open file '/home/zope/instances/instance1/site-buildout_1.0.5/var/filestorage/siteData.fs.lock', mode 'r+' at 0xb714aa88>
------
2010-01-27T05:11:33 WARNING ZODB.lock_file failed to lock <open file '/home/zope/instances/instance1/site-buildout_1.0.5/var/filestorage/siteData.fs.lock', mode 'r+' at 0xb477e5c0>
------
2010-01-27T05:11:33 WARNING ZODB.lock_file failed to lock <open file '/home/zope/instances/instance1/site-buildout_1.0.5/var/filestorage/siteData.fs.lock', mode 'r+' at 0xb477e890>
------
2010-01-27T05:11:33 WARNING ZODB.lock_file failed to lock <open file '/home/zope/instances/instance1/site-buildout_1.0.5/var/filestorage/siteData.fs.lock', mode 'r+' at 0xb477e8d8>
------
[...]
------
2010-01-27T05:14:32 ERROR Zope.ZODBMountPoint Failed to mount database. exceptions.OSError ([Errno 2] No such file or directory: '/home/zope/instances/instance1/site-buildout_1.0.5/var/filestorage/siteData.fs.lock')
Traceback (most recent call last):
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/Products/ZODBMountPoint/MountedObject.py", line 257, in _getOrOpenObject
    conn = self._getMountedConnection(anyjar)
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/Products/ZODBMountPoint/MountedObject.py", line 147, in _getMountedConnection
    self._getDB()
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/Products/ZODBMountPoint/MountedObject.py", line 157, in _getDB
    return getConfiguration().getDatabase(self._path)
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/Zope2/Startup/datatypes.py", line 280, in getDatabase
    db = factory.open(name, self.databases)
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/Zope2/Startup/datatypes.py", line 178, in open
    DB = self.createDB(database_name, databases)
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/Zope2/Startup/datatypes.py", line 175, in createDB
    return ZODBDatabase.open(self, databases)
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/ZODB/config.py", line 107, in open
    storage.close()
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/ZODB/FileStorage/FileStorage.py", line 400, in close
    self._lock_file.close()
  File "/home/zope/instances/instance1/site-buildout_1.0.5/parts/zope2/lib/python/ZODB/lock_file.py", line 79, in close
    os.unlink(self._path)
OSError: [Errno 2] No such file or directory: '/home/zope/instances/instance1/site-buildout_1.0.5/var/filestorage/siteData.fs.loc...

[Alexander Limi (limi)]

Please file this in the Plone issue tracker:

http://dev.plone.org/plone

[Harald Friessnegger (frisi)]

for the record https://dev.plone.org/ticket/10248