[Setup] zeoserver tracebacks following SIGTERM: Error saving index on close() or failed to close storage

Graham Perrin G.J.Perrin at bton.ac.uk
Fri Feb 19 09:56:36 UTC 2010


2010-02-19T07:41:21 daemonizing the process
2010-02-19T07:41:21 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T07:41:21 daemon manager started
2010-02-19T07:41:21 spawned process pid=247
2010-02-19T07:41:21 (247) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T07:41:21 (247) opening storage '1' using BlobStorage
2010-02-19T07:41:21 (247) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T07:41:21 (247) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T07:41:21 (247) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T07:41:21 (247) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T07:41:21 (247) listening on ('127.0.0.1', 8101)
2010-02-19T07:41:43 (247) new connection ('127.0.0.1', 49324):
<ManagedServerConnection ('127.0.0.1', 49324)>
2010-02-19T07:41:43 (127.0.0.1:49324) received handshake 'Z308'
2010-02-19T07:41:48 (247) new connection ('127.0.0.1', 49327):
<ManagedServerConnection ('127.0.0.1', 49327)>
2010-02-19T07:41:48 (127.0.0.1:49327) received handshake 'Z308'
2010-02-19T07:41:56 (247/127.0.0.1:49324) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Blocked transaction restarted.
2010-02-19T07:43:12 (247/127.0.0.1:49327) disconnected
2010-02-19T07:43:38 (247/127.0.0.1:49324) disconnected
2010-02-19T07:44:29 (247) new connection ('127.0.0.1', 49347):
<ManagedServerConnection ('127.0.0.1', 49347)>
2010-02-19T07:44:29 (127.0.0.1:49347) received handshake 'Z308'
2010-02-19T07:45:50 (247) new connection ('127.0.0.1', 49364):
<ManagedServerConnection ('127.0.0.1', 49364)>
2010-02-19T07:45:50 (127.0.0.1:49364) received handshake 'Z308'
2010-02-19T07:45:59 (247/127.0.0.1:49347) disconnected
2010-02-19T07:48:18 (247/127.0.0.1:49364) disconnected
2010-02-19T07:48:27 (247) terminated by SIGTERM
2010-02-19T07:48:27 (247) closing storage '1'
2010-02-19T07:48:27 (247) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T07:48:27 pid 247: exit status 0
2010-02-19T07:48:27 Exiting
2010-02-19T07:50:55 daemonizing the process
2010-02-19T07:50:55 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T07:50:55 daemon manager started
2010-02-19T07:50:55 spawned process pid=17019
2010-02-19T07:50:56 (17019) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T07:50:56 (17019) opening storage '1' using BlobStorage
2010-02-19T07:50:56 (17019) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T07:50:56 (17019) The `lawn` blob directory layout is deprecated
due to scalability issues on some file systems, please consider migrating to
the `bushy` layout.
2010-02-19T07:50:56 (17019) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T07:50:56 (17019) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T07:50:56 (17019) listening on ('127.0.0.1', 8101)
2010-02-19T07:51:29 (17019) new connection ('127.0.0.1', 49400):
<ManagedServerConnection ('127.0.0.1', 49400)>
2010-02-19T07:51:29 (127.0.0.1:49400) received handshake 'Z308'
2010-02-19T07:53:27 (17019/127.0.0.1:49400) disconnected
2010-02-19T07:54:20 (17019) new connection ('127.0.0.1', 49439):
<ManagedServerConnection ('127.0.0.1', 49439)>
2010-02-19T07:54:20 (127.0.0.1:49439) received handshake 'Z308'
2010-02-19T07:55:33 (17019/127.0.0.1:49439) disconnected
2010-02-19T07:55:50 (17019) new connection ('127.0.0.1', 49468):
<ManagedServerConnection ('127.0.0.1', 49468)>
2010-02-19T07:55:50 (127.0.0.1:49468) received handshake 'Z308'
2010-02-19T07:58:56 (17019/127.0.0.1:49468) disconnected
2010-02-19T07:59:14 (17019) new connection ('127.0.0.1', 49491):
<ManagedServerConnection ('127.0.0.1', 49491)>
2010-02-19T07:59:14 (127.0.0.1:49491) received handshake 'Z308'
2010-02-19T08:00:58 (17019/127.0.0.1:49491) disconnected
2010-02-19T08:01:15 (17019) new connection ('127.0.0.1', 49506):
<ManagedServerConnection ('127.0.0.1', 49506)>
2010-02-19T08:01:15 (127.0.0.1:49506) received handshake 'Z308'
2010-02-19T08:17:20 (17019) terminated by SIGTERM
2010-02-19T08:17:20 (17019) closing storage '1'
2010-02-19T08:17:20 daemon manager killed by SIGTERM
2010-02-19T08:17:20 (17019) terminated by SIGTERM
2010-02-19T08:17:20 Error saving index on close()
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 222, in _save_index
    p.dump(info)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T08:17:20 (17019) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:18:18 daemonizing the process
2010-02-19T08:18:18 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:18:18 daemon manager started
2010-02-19T08:18:18 spawned process pid=229
2010-02-19T08:18:18 (229) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:18:18 (229) opening storage '1' using BlobStorage
2010-02-19T08:18:19 (229) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T08:18:19 (229) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T08:18:19 (229) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T08:18:19 (229) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T08:18:19 (229) listening on ('127.0.0.1', 8101)
2010-02-19T08:18:41 (229) new connection ('127.0.0.1', 49324):
<ManagedServerConnection ('127.0.0.1', 49324)>
2010-02-19T08:18:41 (127.0.0.1:49324) received handshake 'Z308'
2010-02-19T08:18:46 (229) new connection ('127.0.0.1', 49326):
<ManagedServerConnection ('127.0.0.1', 49326)>
2010-02-19T08:18:46 (127.0.0.1:49326) received handshake 'Z308'
2010-02-19T08:41:13 (229) terminated by SIGTERM
2010-02-19T08:41:13 daemon manager killed by SIGTERM
2010-02-19T08:41:13 (229) closing storage '1'
2010-02-19T08:41:13 (229) terminated by SIGTERM
2010-02-19T08:41:13 Error saving index on close()
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 222, in _save_index
    p.dump(info)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T08:41:13 (229) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:12 Unlinking stale socket
/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeo.zdsock; sleep 1
2010-02-19T08:42:12 daemonizing the process
2010-02-19T08:42:12 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:42:12 daemon manager started
2010-02-19T08:42:12 spawned process pid=252
2010-02-19T08:42:12 Another zrdun is already up using socket
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeo.zdsock':
status=running
now=1266568932.710201
mood=1
delay=0
backoff=0
lasttime=1266568932.708524
application=252
manager=251
backofflimit=10
filename='/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver/bin/runzeo'
args=['/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver/bin/runzeo']
2010-02-19T08:42:12 (252) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:12 (252) opening storage '1' using BlobStorage
2010-02-19T08:42:13 daemonizing the process
2010-02-19T08:42:13 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:42:13 daemon manager started
2010-02-19T08:42:13 spawned process pid=287
2010-02-19T08:42:13 (252) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T08:42:13 (252) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T08:42:13 (252) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T08:42:14 (252) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T08:42:14 (252) listening on ('127.0.0.1', 8101)
2010-02-19T08:42:14 (287) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:14 (287) opening storage '1' using BlobStorage
2010-02-19T08:42:14 Error locking file
/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs.lock;
pid=UNKNOWN
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/lock_file.py",
line 80, in __init__
    _lock_file(fp)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/lock_file.py",
line 59, in _lock_file
    raise LockError("Couldn't lock %r" % file.name)
LockError: Couldn't lock
'/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs.lock'
2010-02-19T08:42:14 (287) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:14 sleep 1 to avoid rapid restarts
2010-02-19T08:42:14 pid 287: exit status 1
2010-02-19T08:42:15 spawned process pid=344
2010-02-19T08:42:16 (252) new connection ('127.0.0.1', 49180):
<ManagedServerConnection ('127.0.0.1', 49180)>
2010-02-19T08:42:16 (252/127.0.0.1:49180) disconnected
2010-02-19T08:42:16 sleep 2 to avoid rapid restarts
2010-02-19T08:42:16 pid 344: exit status 2; exiting now
2010-02-19T08:53:03 (252) terminated by SIGTERM
2010-02-19T08:53:03 (252) closing storage '1'
2010-02-19T08:53:03 daemon manager killed by SIGTERM
2010-02-19T08:53:03 (252) terminated by SIGTERM
2010-02-19T08:53:03 Error saving index on close()
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 222, in _save_index
    p.dump(info)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T08:54:01 daemonizing the process
2010-02-19T08:54:01 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:54:01 daemon manager started
2010-02-19T08:54:01 spawned process pid=248
2010-02-19T08:54:01 (248) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:54:01 (248) opening storage '1' using BlobStorage
2010-02-19T08:54:03 (248) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T08:54:03 (248) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T08:54:03 (248) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T08:54:03 (248) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T08:54:03 (248) listening on ('127.0.0.1', 8101)
2010-02-19T08:54:25 (248) new connection ('127.0.0.1', 49310):
<ManagedServerConnection ('127.0.0.1', 49310)>
2010-02-19T08:54:25 (248) new connection ('127.0.0.1', 49311):
<ManagedServerConnection ('127.0.0.1', 49311)>
2010-02-19T08:54:25 (127.0.0.1:49310) received handshake 'Z308'
2010-02-19T08:54:25 (127.0.0.1:49311) received handshake 'Z308'
2010-02-19T08:58:54 (248/127.0.0.1:49310) disconnected
2010-02-19T08:59:24 (248/127.0.0.1:49311) disconnected
2010-02-19T08:59:47 (248) new connection ('127.0.0.1', 49343):
<ManagedServerConnection ('127.0.0.1', 49343)>
2010-02-19T08:59:47 (127.0.0.1:49343) received handshake 'Z308'
2010-02-19T09:13:18 (248) terminated by SIGTERM
2010-02-19T09:13:18 (248) closing storage '1'
2010-02-19T09:13:18 daemon manager killed by SIGTERM
2010-02-19T09:13:18 (248) terminated by SIGTERM
2010-02-19T09:13:18 daemon manager killed by SIGTERM
2010-02-19T09:13:18 (248) failed to close storage '1'
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 269, in close_storages
    storage.close()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T09:14:18 Unlinking stale socket
/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeo.zdsock; sleep 1
2010-02-19T09:14:19 daemonizing the process
2010-02-19T09:14:19 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T09:14:19 daemon manager started
2010-02-19T09:14:19 spawned process pid=280
2010-02-19T09:14:20 (280) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T09:14:20 (280) opening storage '1' using BlobStorage
2010-02-19T09:14:22 (280) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T09:14:22 (280) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T09:14:22 (280) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T09:14:22 (280) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T09:14:22 (280) listening on ('127.0.0.1', 8101)
2010-02-19T09:14:38 (280) new connection ('127.0.0.1', 49326):
<ManagedServerConnection ('127.0.0.1', 49326)>
2010-02-19T09:14:38 (127.0.0.1:49326) received handshake 'Z308'
2010-02-19T09:19:03 (280/127.0.0.1:49326) disconnected
2010-02-19T09:20:04 (280) new connection ('127.0.0.1', 49361):
<ManagedServerConnection ('127.0.0.1', 49361)>
2010-02-19T09:20:04 (127.0.0.1:49361) received handshake 'Z308'
2010-02-19T07:41:21 daemonizing the process
2010-02-19T07:41:21 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T07:41:21 daemon manager started
2010-02-19T07:41:21 spawned process pid=247
2010-02-19T07:41:21 (247) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T07:41:21 (247) opening storage '1' using BlobStorage
2010-02-19T07:41:21 (247) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T07:41:21 (247) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T07:41:21 (247) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T07:41:21 (247) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T07:41:21 (247) listening on ('127.0.0.1', 8101)
2010-02-19T07:41:43 (247) new connection ('127.0.0.1', 49324):
<ManagedServerConnection ('127.0.0.1', 49324)>
2010-02-19T07:41:43 (127.0.0.1:49324) received handshake 'Z308'
2010-02-19T07:41:48 (247) new connection ('127.0.0.1', 49327):
<ManagedServerConnection ('127.0.0.1', 49327)>
2010-02-19T07:41:48 (127.0.0.1:49327) received handshake 'Z308'
2010-02-19T07:41:56 (247/127.0.0.1:49324) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Blocked transaction restarted.
2010-02-19T07:41:56 (247/127.0.0.1:49327) Transaction blocked waiting for
storage. Clients waiting: 1.
2010-02-19T07:41:56 (247/127.0.0.1:49324) Blocked transaction restarted.
2010-02-19T07:43:12 (247/127.0.0.1:49327) disconnected
2010-02-19T07:43:38 (247/127.0.0.1:49324) disconnected
2010-02-19T07:44:29 (247) new connection ('127.0.0.1', 49347):
<ManagedServerConnection ('127.0.0.1', 49347)>
2010-02-19T07:44:29 (127.0.0.1:49347) received handshake 'Z308'
2010-02-19T07:45:50 (247) new connection ('127.0.0.1', 49364):
<ManagedServerConnection ('127.0.0.1', 49364)>
2010-02-19T07:45:50 (127.0.0.1:49364) received handshake 'Z308'
2010-02-19T07:45:59 (247/127.0.0.1:49347) disconnected
2010-02-19T07:48:18 (247/127.0.0.1:49364) disconnected
2010-02-19T07:48:27 (247) terminated by SIGTERM
2010-02-19T07:48:27 (247) closing storage '1'
2010-02-19T07:48:27 (247) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T07:48:27 pid 247: exit status 0
2010-02-19T07:48:27 Exiting
2010-02-19T07:50:55 daemonizing the process
2010-02-19T07:50:55 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T07:50:55 daemon manager started
2010-02-19T07:50:55 spawned process pid=17019
2010-02-19T07:50:56 (17019) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T07:50:56 (17019) opening storage '1' using BlobStorage
2010-02-19T07:50:56 (17019) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T07:50:56 (17019) The `lawn` blob directory layout is deprecated
due to scalability issues on some file systems, please consider migrating to
the `bushy` layout.
2010-02-19T07:50:56 (17019) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T07:50:56 (17019) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T07:50:56 (17019) listening on ('127.0.0.1', 8101)
2010-02-19T07:51:29 (17019) new connection ('127.0.0.1', 49400):
<ManagedServerConnection ('127.0.0.1', 49400)>
2010-02-19T07:51:29 (127.0.0.1:49400) received handshake 'Z308'
2010-02-19T07:53:27 (17019/127.0.0.1:49400) disconnected
2010-02-19T07:54:20 (17019) new connection ('127.0.0.1', 49439):
<ManagedServerConnection ('127.0.0.1', 49439)>
2010-02-19T07:54:20 (127.0.0.1:49439) received handshake 'Z308'
2010-02-19T07:55:33 (17019/127.0.0.1:49439) disconnected
2010-02-19T07:55:50 (17019) new connection ('127.0.0.1', 49468):
<ManagedServerConnection ('127.0.0.1', 49468)>
2010-02-19T07:55:50 (127.0.0.1:49468) received handshake 'Z308'
2010-02-19T07:58:56 (17019/127.0.0.1:49468) disconnected
2010-02-19T07:59:14 (17019) new connection ('127.0.0.1', 49491):
<ManagedServerConnection ('127.0.0.1', 49491)>
2010-02-19T07:59:14 (127.0.0.1:49491) received handshake 'Z308'
2010-02-19T08:00:58 (17019/127.0.0.1:49491) disconnected
2010-02-19T08:01:15 (17019) new connection ('127.0.0.1', 49506):
<ManagedServerConnection ('127.0.0.1', 49506)>
2010-02-19T08:01:15 (127.0.0.1:49506) received handshake 'Z308'
2010-02-19T08:17:20 (17019) terminated by SIGTERM
2010-02-19T08:17:20 (17019) closing storage '1'
2010-02-19T08:17:20 daemon manager killed by SIGTERM
2010-02-19T08:17:20 (17019) terminated by SIGTERM
2010-02-19T08:17:20 Error saving index on close()
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 222, in _save_index
    p.dump(info)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T08:17:20 (17019) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:18:18 daemonizing the process
2010-02-19T08:18:18 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:18:18 daemon manager started
2010-02-19T08:18:18 spawned process pid=229
2010-02-19T08:18:18 (229) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:18:18 (229) opening storage '1' using BlobStorage
2010-02-19T08:18:19 (229) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T08:18:19 (229) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T08:18:19 (229) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T08:18:19 (229) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T08:18:19 (229) listening on ('127.0.0.1', 8101)
2010-02-19T08:18:41 (229) new connection ('127.0.0.1', 49324):
<ManagedServerConnection ('127.0.0.1', 49324)>
2010-02-19T08:18:41 (127.0.0.1:49324) received handshake 'Z308'
2010-02-19T08:18:46 (229) new connection ('127.0.0.1', 49326):
<ManagedServerConnection ('127.0.0.1', 49326)>
2010-02-19T08:18:46 (127.0.0.1:49326) received handshake 'Z308'
2010-02-19T08:41:13 (229) terminated by SIGTERM
2010-02-19T08:41:13 daemon manager killed by SIGTERM
2010-02-19T08:41:13 (229) closing storage '1'
2010-02-19T08:41:13 (229) terminated by SIGTERM
2010-02-19T08:41:13 Error saving index on close()
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 222, in _save_index
    p.dump(info)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T08:41:13 (229) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:12 Unlinking stale socket
/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeo.zdsock; sleep 1
2010-02-19T08:42:12 daemonizing the process
2010-02-19T08:42:12 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:42:12 daemon manager started
2010-02-19T08:42:12 spawned process pid=252
2010-02-19T08:42:12 Another zrdun is already up using socket
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeo.zdsock':
status=running
now=1266568932.710201
mood=1
delay=0
backoff=0
lasttime=1266568932.708524
application=252
manager=251
backofflimit=10
filename='/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver/bin/runzeo'
args=['/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver/bin/runzeo']
2010-02-19T08:42:12 (252) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:12 (252) opening storage '1' using BlobStorage
2010-02-19T08:42:13 daemonizing the process
2010-02-19T08:42:13 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:42:13 daemon manager started
2010-02-19T08:42:13 spawned process pid=287
2010-02-19T08:42:13 (252) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T08:42:13 (252) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T08:42:13 (252) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T08:42:14 (252) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T08:42:14 (252) listening on ('127.0.0.1', 8101)
2010-02-19T08:42:14 (287) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:14 (287) opening storage '1' using BlobStorage
2010-02-19T08:42:14 Error locking file
/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs.lock;
pid=UNKNOWN
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/lock_file.py",
line 80, in __init__
    _lock_file(fp)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/lock_file.py",
line 59, in _lock_file
    raise LockError("Couldn't lock %r" % file.name)
LockError: Couldn't lock
'/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs.lock'
2010-02-19T08:42:14 (287) removed PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:42:14 sleep 1 to avoid rapid restarts
2010-02-19T08:42:14 pid 287: exit status 1
2010-02-19T08:42:15 spawned process pid=344
2010-02-19T08:42:16 (252) new connection ('127.0.0.1', 49180):
<ManagedServerConnection ('127.0.0.1', 49180)>
2010-02-19T08:42:16 (252/127.0.0.1:49180) disconnected
2010-02-19T08:42:16 sleep 2 to avoid rapid restarts
2010-02-19T08:42:16 pid 344: exit status 2; exiting now
2010-02-19T08:53:03 (252) terminated by SIGTERM
2010-02-19T08:53:03 (252) closing storage '1'
2010-02-19T08:53:03 daemon manager killed by SIGTERM
2010-02-19T08:53:03 (252) terminated by SIGTERM
2010-02-19T08:53:03 Error saving index on close()
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 222, in _save_index
    p.dump(info)
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T08:54:01 daemonizing the process
2010-02-19T08:54:01 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T08:54:01 daemon manager started
2010-02-19T08:54:01 spawned process pid=248
2010-02-19T08:54:01 (248) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T08:54:01 (248) opening storage '1' using BlobStorage
2010-02-19T08:54:03 (248) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T08:54:03 (248) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T08:54:03 (248) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T08:54:03 (248) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T08:54:03 (248) listening on ('127.0.0.1', 8101)
2010-02-19T08:54:25 (248) new connection ('127.0.0.1', 49310):
<ManagedServerConnection ('127.0.0.1', 49310)>
2010-02-19T08:54:25 (248) new connection ('127.0.0.1', 49311):
<ManagedServerConnection ('127.0.0.1', 49311)>
2010-02-19T08:54:25 (127.0.0.1:49310) received handshake 'Z308'
2010-02-19T08:54:25 (127.0.0.1:49311) received handshake 'Z308'
2010-02-19T08:58:54 (248/127.0.0.1:49310) disconnected
2010-02-19T08:59:24 (248/127.0.0.1:49311) disconnected
2010-02-19T08:59:47 (248) new connection ('127.0.0.1', 49343):
<ManagedServerConnection ('127.0.0.1', 49343)>
2010-02-19T08:59:47 (127.0.0.1:49343) received handshake 'Z308'
2010-02-19T09:13:18 (248) terminated by SIGTERM
2010-02-19T09:13:18 (248) closing storage '1'
2010-02-19T09:13:18 daemon manager killed by SIGTERM
2010-02-19T09:13:18 (248) terminated by SIGTERM
2010-02-19T09:13:18 daemon manager killed by SIGTERM
2010-02-19T09:13:18 (248) failed to close storage '1'
Traceback (most recent call last):
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 269, in close_storages
    storage.close()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZODB/FileStorage/FileStorage.py",
line 374, in close
    self._save_index()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 208, in wrapper
    method()
  File
"/Volumes/SSD/flashplone/Plone/buildout-cache/eggs/ZODB3-3.8.4-py2.4-macosx-10.6-x86_64.egg/ZEO/runzeo.py",
line 249, in handle_sigterm
    sys.exit(0)
SystemExit: 0
2010-02-19T09:14:18 Unlinking stale socket
/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeo.zdsock; sleep 1
2010-02-19T09:14:19 daemonizing the process
2010-02-19T09:14:19 set current directory:
'/Volumes/SSD/flashplone/Plone/zeocluster/parts/zeoserver'
2010-02-19T09:14:19 daemon manager started
2010-02-19T09:14:19 spawned process pid=280
2010-02-19T09:14:20 (280) created PID file
'/Volumes/SSD/flashplone/Plone/zeocluster/var/zeoserver/zeoserver.pid'
2010-02-19T09:14:20 (280) opening storage '1' using BlobStorage
2010-02-19T09:14:22 (280) Blob directory
`/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage` has layout marker
set. Selected `lawn` layout. 
2010-02-19T09:14:22 (280) The `lawn` blob directory layout is deprecated due
to scalability issues on some file systems, please consider migrating to the
`bushy` layout.
2010-02-19T09:14:22 (280) Blob dir
/Volumes/SSD/flashplone/Plone/zeocluster/var/blobstorage/ has insecure mode
setting
2010-02-19T09:14:22 (280) StorageServer created RW with storages:
1:RW:/Volumes/SSD/flashplone/Plone/zeocluster/var/filestorage/Data.fs
2010-02-19T09:14:22 (280) listening on ('127.0.0.1', 8101)
2010-02-19T09:14:38 (280) new connection ('127.0.0.1', 49326):
<ManagedServerConnection ('127.0.0.1', 49326)>
2010-02-19T09:14:38 (127.0.0.1:49326) received handshake 'Z308'
2010-02-19T09:19:03 (280/127.0.0.1:49326) disconnected
2010-02-19T09:20:04 (280) new connection ('127.0.0.1', 49361):
<ManagedServerConnection ('127.0.0.1', 49361)>
2010-02-19T09:20:04 (127.0.0.1:49361) received handshake 'Z308'

I wonder what causes the tracebacks. 

Environment

Plone 3.3.4
ZEO cluster, two clients
Mac OS X Server 10.6.2, Intel, 64-bit kernel and extensions
spinning and solid state disks.

Plone installation, FileStorage and BLOBs are on the solid state drive 
/Volumes/SSD

To start the cluster automatically following start of the OS, I do *not* use
legacy
/Library/StartupItems
— instead, I use launchd

reunion:~ centrimadmin$ ls -l /Library/LaunchDaemons/
total 96
-rw-r--r--@ 1 root  wheel  623 Feb 18 23:47
collective.recipe.backup.plone-zeo-filestorage.plist
-rw-r--r--  1 root  wheel  802 Feb 18 16:07 com.barebones.textwrangler.plist
-rw-r--r--@ 1 root  wheel  494 Jan 30 15:33 org.apache.lucene.solr.plist
lrwxr-xr-x  1 root  wheel   66 Feb 18 12:16
org.freedesktop.dbus-system.plist ->
/opt/local/Library/LaunchDaemons/org.freedesktop.dbus-system.plist
-rw-r--r--@ 1 root  wheel  611 Feb 19 08:51
org.plone.zeo-cluster-client1.plist
-rw-r--r--@ 1 root  wheel  611 Feb 19 09:32
org.plone.zeo-cluster-client2.plist
-rw-r--r--@ 1 root  wheel  614 Feb 19 08:35
org.plone.zeo-cluster-zeoserver.plist

(<http://dev.plone.org/old/plone/ticket/10133> is work in progress, I'll
update that ticket after resolving issues such as this.)
-- 
View this message in context: http://n2.nabble.com/zeoserver-tracebacks-following-SIGTERM-Error-saving-index-on-close-or-failed-to-close-storage-tp4596948p4596948.html
Sent from the Installation, Setup, Upgrades mailing list archive at Nabble.com.



More information about the Setup mailing list