Strange errors preventing our Zope instance from starting
Hello, We are running a Zope 2.5.1 (yes, I know, old) version on one of our servers and yesterday we started getting these errors (quite a lot of them) on the error log: 2004-01-05T11:06:05 ERROR(200) ZODB Couldn't load state for '\x00\x00\x00\x00\x00y0s' Traceback (innermost last): File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/Connection.py, line 447, in setstate File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 582, in load (Object: /var/Zope/instances/cc251/var/Data.fs) File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 557, in _load (Object: /var/Zope/instances/cc251/var/Data.fs) POSKeyError: 0000000000793073 And then this: 2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: /var/Zope/instances/cc251/var/Data.fs truncated, possib ly due to damaged records at 2137747449 ------ 2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: Writing truncated data from /var/Zope/instances/cc251/v ar/Data.fs to /var/Zope/instances/cc251/var/Data.fs.tr0 ------ [ ... more logs in here ... ] ------ 2004-01-06T06:24:52 PROBLEM(100) OFS.Application Duplicate Product name After loading Product 'SiteAccess' from '/var/Zope/instances/cc251/Products', I skipped the one in '/var/Zope/Zope-2.5.1-src/lib/python/Products'. ------ 2004-01-06T06:24:53 PANIC(300) z2 Startup exception Traceback (innermost last): File /var/Zope/Zope-2.5.1-src/z2.py, line 571, in ? File <string>, line 1, in ? File /var/Zope/Zope-2.5.1-src/lib/python/Zope/__init__.py, line 37, in ? File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 213, in __init__ File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/lock_file.py, line 33, in lock_file StorageSystemError: Could not lock the database file. There must be another process that has opened the file. <p> So this morning we tried a "restart" and it didn't work, some python process was refusing to die, even with "kill -9" :( So we restarted the server and this is what we get now in the error log: 2004-01-06T09:40:51 PROBLEM(100) Init Ambiguous name for method of Products.PlugIns.PlugIns.PlugInGroup: "ma nage_workspace" != "manage_main" ------ 2004-01-06T09:40:51 PROBLEM(100) Init Ambiguous name for method of Products.LoginManager.LoginMethods.BasicC ookieLogin: "manage_propertiesForm" != "manage_main" ------ 2004-01-06T09:40:52 PROBLEM(100) Init Ambiguous name for method of Products.PythonMethod.PythonMethod.Python Method: "manage" != "manage_main" ------ 2004-01-06T09:40:52 PROBLEM(100) Init Ambiguous name for method of Products.SiteAccess.SiteRoot.SiteRoot: "m anage" != "manage_main" ------ 2004-01-06T09:40:52 PROBLEM(100) OFS.Application Duplicate Product name After loading Product 'SiteAccess' from '/var/Zope/instances/cc251/Products', I skipped the one in '/var/Zope/Zope-2.5.1-src/lib/python/Products'. ------ 2004-01-06T09:42:21 INFO(0) ZODB Opening database for mounting: '158998424_1044618368.927185' ------ 2004-01-06T09:42:21 INFO(0) ZODB Mounted database '158998424_1044618368.927185' at /temp_folder ------ 2004-01-06T09:42:22 PROBLEM(100) Zope No such file or directory: /var/Zope/instances/cc251/Products/PlugIns/ help ------ 2004-01-06T09:42:23 INFO(0) Zope New disk product detected, determining if we need to fix up any ZClasses. ------ 2004-01-06T09:42:23 INFO(0) ZServer HTTP server started at Tue Jan 6 10:42:23 2004 Hostname: activism.greenpeace.org Port: 8085 ------ 2004-01-06T09:46:11 PROBLEM(100) ZODB Could not import class 'Connection' from module 'Products.ZPoPyDA.DA' ------ So, I think there is something strange here but I don't know what the issue might be. Any suggestion? Cheers /B -- Bruno Mattarollo <bruno.mattarollo@diala.greenpeace.org> Head of IT - Greenpeace International [ http://www.greenpeace.org/ ]
On Tue, Jan 06, 2004 at 11:02:07AM +0100, Bruno Mattarollo wrote:
Hello,
We are running a Zope 2.5.1 (yes, I know, old) version on one of our servers and yesterday we started getting these errors (quite a lot of them) on the error log:
2004-01-05T11:06:05 ERROR(200) ZODB Couldn't load state for '\x00\x00\x00\x00\x00y0s' Traceback (innermost last): File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/Connection.py, line 447, in setstate File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 582, in load (Object: /var/Zope/instances/cc251/var/Data.fs) File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 557, in _load (Object: /var/Zope/instances/cc251/var/Data.fs) POSKeyError: 0000000000793073
And then this:
2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: /var/Zope/instances/cc251/var/Data.fs truncated, possib ly due to damaged records at 2137747449
------ 2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: Writing truncated data from /var/Zope/instances/cc251/v ar/Data.fs to /var/Zope/instances/cc251/var/Data.fs.tr0
You have some damage in your ZODB. You should run fsrecover.py on a *copy* of this database and see if you can fix these errors. Alternatively, restore a backup of the database. Note that some versions of fsrecover.py were broken. Check the archives, I don't remember if 2.5.1 was OK. I remember that 2.6.2 is OK, 2.6.0 was not. After recovery, try checking the output with utilities/ZODBTools/fstest.py. I don't know what causes "Writing truncated data", you might ask on the zodb-dev list.
So this morning we tried a "restart" and it didn't work, some python process was refusing to die, even with "kill -9" :( So we restarted the server and this is what we get now in the error log:
2004-01-06T09:40:51 PROBLEM(100) Init Ambiguous name for method of Products.PlugIns.PlugIns.PlugInGroup: "ma nage_workspace" != "manage_main" ------ 2004-01-06T09:40:51 PROBLEM(100) Init Ambiguous name for method of Products.LoginManager.LoginMethods.BasicC ookieLogin: "manage_propertiesForm" != "manage_main" ------ 2004-01-06T09:40:52 PROBLEM(100) Init Ambiguous name for method of Products.PythonMethod.PythonMethod.Python Method: "manage" != "manage_main" ------ 2004-01-06T09:40:52 PROBLEM(100) Init Ambiguous name for method of Products.SiteAccess.SiteRoot.SiteRoot: "m anage" != "manage_main" ------ 2004-01-06T09:40:52 PROBLEM(100) OFS.Application Duplicate Product name After loading Product 'SiteAccess' from '/var/Zope/instances/cc251/Products', I skipped the one in '/var/Zope/Zope-2.5.1-src/lib/python/Products'. ------ 2004-01-06T09:42:21 INFO(0) ZODB Opening database for mounting: '158998424_1044618368.927185' ------ 2004-01-06T09:42:21 INFO(0) ZODB Mounted database '158998424_1044618368.927185' at /temp_folder ------ 2004-01-06T09:42:22 PROBLEM(100) Zope No such file or directory: /var/Zope/instances/cc251/Products/PlugIns/ help ------ 2004-01-06T09:42:23 INFO(0) Zope New disk product detected, determining if we need to fix up any ZClasses. ------ 2004-01-06T09:42:23 INFO(0) ZServer HTTP server started at Tue Jan 6 10:42:23 2004 Hostname: activism.greenpeace.org Port: 8085
The last message looks like you're up... none of the above issues should prevent startup.
------ 2004-01-06T09:46:11 PROBLEM(100) ZODB Could not import class 'Connection' from module 'Products.ZPoPyDA.DA'
That's a 3rd-party product... looks like it's broken? Did it work before? Anyway, this should not prevent zope from starting. -- Paul Winkler http://www.slinkp.com Look! Up in the sky! It's SEMI LUGGAGE CAPTAIN! (random hero from isometric.spaceninja.com)
Hello Paul, On Jan 6, 2004, at 18:02, Paul Winkler wrote:
The last message looks like you're up... none of the above issues should prevent startup.
Ok, then if I understand correctly it means that the DB was corrupted and when starting it was truncated automatically to remove those transactions. Smooth.
------ 2004-01-06T09:46:11 PROBLEM(100) ZODB Could not import class 'Connection' from module 'Products.ZPoPyDA.DA'
That's a 3rd-party product... looks like it's broken? Did it work before? Anyway, this should not prevent zope from starting.
Yes, an old product indeed. The strange thing is that it started after 20 minutes or so ... Anyways, I will keep an eye on it. Thanks for your answer! /B -- Bruno Mattarollo <bruno.mattarollo@diala.greenpeace.org> Head of IT - Greenpeace International [ http://www.greenpeace.org/ ]
Bruno Mattarollo wrote at 2004-1-6 11:02 +0100:
We are running a Zope 2.5.1 (yes, I know, old) version on one of our servers and yesterday we started getting these errors (quite a lot of them) on the error log:
2004-01-05T11:06:05 ERROR(200) ZODB Couldn't load state for '\x00\x00\x00\x00\x00y0s' Traceback (innermost last): File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/Connection.py, line 447, in setstate File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 582, in load (Object: /var/Zope/instances/cc251/var/Data.fs) File /var/Zope/Zope-2.5.1-src/lib/python/ZODB/FileStorage.py, line 557, in _load (Object: /var/Zope/instances/cc251/var/Data.fs) POSKeyError: 0000000000793073
Your ZODB became inconsistent: there is a reference to an object with object id "0x793073" which is not in the database. It would not be bad to have a recent backup...
2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: /var/Zope/instances/cc251/var/Data.fs truncated, possib ly due to damaged records at 2137747449
This is dangerously near the 2 GB limit. Are you sure you are using a Python with large file support? -- Dieter
On Tue, Jan 06, 2004 at 08:38:59PM +0100, Dieter Maurer wrote:
2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: /var/Zope/instances/cc251/var/Data.fs truncated, possib ly due to damaged records at 2137747449
This is dangerously near the 2 GB limit.
Are you sure you are using a Python with large file support?
Good catch, I didn't spot the number. 2137747449 is only about 9 MB below the 2 GB mark. Bruno, you should definitely look into that. To test for largefile support, use the test provided with python. Your path may vary, but I do this: $ python2.1 /usr/local/lib/python2.1/test/test_largefile.py The output should look something like the following, with no reported errors: create large file via seek (may be sparse file) ... 2500000001L =?= 2500000001L ... yes check file size with os.fstat check file size with os.stat 2500000001L =?= 2500000001L ... yes play around with seek() and read() with the built largefile 0L =?= 0 ... yes '\x00' =?= '\x00' ... yes 1L =?= 1 ... yes 0L =?= 0 ... yes 0L =?= 0 ... yes 42L =?= 42 ... yes 42L =?= 42 ... yes 84L =?= 84 ... yes 84L =?= 84 ... yes 2500000001L =?= 2500000001L ... yes 2499999991L =?= 2499999991L ... yes 0L =?= 0 ... yes 2500000000L =?= 2500000000L ... yes 'a' =?= 'a' ... yes play around with os.lseek() with the built largefile 0L =?= 0 ... yes 42L =?= 42 ... yes 84L =?= 84 ... yes 84L =?= 84 ... yes 2500000001L =?= 2500000001L ... yes 2499999991L =?= 2499999991L ... yes 0L =?= 0 ... yes 2500000000L =?= 2500000000L ... yes 'a' =?= 'a' ... yes @test exists: 0 -- Paul Winkler http://www.slinkp.com Look! Up in the sky! It's GAMMA NINJA FINGER! (random hero from isometric.spaceninja.com)
Thanks Dieter and Paul, it was indeed the 2GB limit! Cheers /B On Jan 6, 2004, at 21:42, Paul Winkler wrote:
On Tue, Jan 06, 2004 at 08:38:59PM +0100, Dieter Maurer wrote:
2004-01-06T06:05:06 PROBLEM(100) ZODB FS FS21 warn: /var/Zope/instances/cc251/var/Data.fs truncated, possib ly due to damaged records at 2137747449
This is dangerously near the 2 GB limit.
Are you sure you are using a Python with large file support?
Good catch, I didn't spot the number. 2137747449 is only about 9 MB below the 2 GB mark.
Bruno, you should definitely look into that. To test for largefile support, use the test provided with python. Your path may vary, but I do this:
-- Bruno Mattarollo <bruno.mattarollo@diala.greenpeace.org> Head of IT - Greenpeace International [ http://www.greenpeace.org/ ]
participants (3)
-
Bruno Mattarollo -
Dieter Maurer -
Paul Winkler