Backup aborted - why? (dirstor 1.1.9)

Today I tried to run a full backup on one of our
ZEO servers that runs on DirectoryStorage 1.1.9.

It looks like the backup failed and DirectoryStorage
took itself out of snapshot mode, but I see nothing
in the logs to indicate why.
Any ideas?

The backup shell script is a simple wrapper that
mainly just logs the date and runs this command:

python2.3 snapshot.py /zope/ZopeInstanceHome/var/DirStor - python2.3 backup.py full 

I ran it under nohup and this is the entire contents of nohup.out
(IP address removed):

Starting at Tue Dec 28 10:44:21 EST 2004
Entered snapshot using http://xxx.xxx.xxx.197:8780/DSToolkit
This is backup sequence number 3
Creating full backup '/zope/ZopeInstanceHome/var/DirStor/backups/backup-3.tgz'


That's it. The process is definitely long gone.
The backup file was last updated about 1 hour later,
and never got renamed to backup-3.tgz:

$ ls -lart /zope/ZopeInstanceHome/var/DirStor/backups/
total 6664841
drwxr-xr-x    8 zope     zope          192 Jan 13  2004 ..
-rw-r-----    1 zope     zope     2181562900 Jan 13  2004 backup-1.tgz
-rw-r-----    1 zope     zope     2455399662 May 17  2004 backup-2.tgz
-rw-r--r--    1 zope     zope          273 May 17  2004 tindex
drwxr-xr-x    2 zope     zope          176 Dec 28 11:00 .
-rw-r-----    1 zope     zope     2187825152 Dec 28 11:45 .tmp-backup-3.tgz


Note that this server was recently upgraded from Zope 2.6.2 to 2.7.3
Apparently my cron backup job never worked on this box so it hasn't 
been backed up in many months, since long before the upgrade.

Here's the ZEO log for the time in question:

2004-12-28T10:42:38 INFO(0) DirectoryStorage Flushing 54 transactions (age limit
 reached)
------
2004-12-28T10:42:40 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:34 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:35 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:35 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:36 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:37 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:38 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T10:47:40 INFO(0) ZSS:23067/xxx.xxx.xxx.197:34926 Transaction released s
torage lock
------
2004-12-28T11:00:06 INFO(0) ZSS:23067 new connection ('xxx.xxx.xxx.196', 35317): <
ManagedServerConnection ('xxx.xxx.xxx.196', 35317)>
------
2004-12-28T11:00:06 INFO(0) zrpc-conn:xxx.xxx.xxx.196:35317 received handshake 'Z2
00'
------
2004-12-28T11:00:06 INFO(0) ZSS:23067/xxx.xxx.xxx.196:35317 unknown storage_id: 1
------
2004-12-28T11:00:06 INFO(0) zrpc-conn:xxx.xxx.xxx.196:35317 register() raised exce
ption: unknown storage: 1
Traceback (most recent call last):
  File "/zope/Zope-2.7.3-0-SoftwareHome/lib/python/ZEO/zrpc/connection.py", line
 267, in handle_request
    ret = meth(*args)
  File "/zope/Zope-2.7.3-0-SoftwareHome/lib/python/ZEO/StorageServer.py", line 2
07, in register
    raise ValueError, "unknown storage: %s" % storage_id
ValueError: unknown storage: 1
------
2004-12-28T11:00:09 INFO(0) DirectoryStorage Flushing 8 transactions (snapshot)
------
2004-12-28T11:00:09 INFO(0) DirectoryStorage Entered snapshot mode 'user/prod-ze
o-knox01-1466'
------
2004-12-28T11:49:47 INFO(0) DirectoryStorage Preparing to leave snapshot mode 'u
ser/prod-zeo-knox01-1466'
------
2004-12-28T11:49:47 INFO(0) DirectoryStorage Left snapshot mode 'recombining/use
r/prod-zeo-knox01-1466'
------


The only things interesting there to me are 1) the failed connection from 196,
which is a server that was supposed to be decomissioned but we
accidentally left an old zope (2.6.4) with an outdated zeo config running
on it.  I've since shut that zope down.
And 2) snapshot mode was entered a full 15 minutes after the backup
process was started. Is that normal??


-- 

Paul Winkler
http://www.slinkp.com


-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users.
Discover which products truly live up to the hype. Start reading now. 
http://productguide.itmanagersjournal.com/