Submitted by : SimonMichael at: 2004-06-23T09:54:54+00:00 (13 years ago)
Name :
Category : Severity : Status :
Optional subject :  
Optional comment :

Cf ZopeIssue:1395 , PythonBug:983311 .

This affects zopewiki, zwiki.org and other sites on this server. Requests to the site do not fail, just hang. Event log shows no error, just no activity after a certain point. No obvious troublesome urls appear in Z2.log or access.log before the hang. Zope does not appear to be using too much memory, and CPU is idle. One or more python processes may have gone away. After a hang, zopectl start appears to succeed but doesn't fix it. killall -9 python; zeoctl start; zopectl start fixes it.

python processes after hang:

 # ps auxww |grep python
 root     20225  0.0  0.0  7952 3472 ?        S    Jun22   0:01 /usr/bin/python /zope/lib/python/zdaemon/zdrun.py -S /zope/lib/python/ZEO/zeoctl.xml -C /zeo/etc/zeo.conf /zeo/bin/runzeo
 root     20256  0.0  0.1 13080 10812 ?       S    Jun22   0:07 /usr/bin/python /zope/lib/python/ZEO/runzeo.py -C /zeo/etc/zeo.conf
 nobody   22918  0.0  1.4 90904 83724 ?       S    Jun22   0:00 /usr/bin/python /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf
 nobody   22920  0.0  1.4 90904 83724 ?       S    Jun22   0:44 /usr/bin/python /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf

Z2.log before & after hang:

 127.0.0.1 - Anonymous [22/Jun/2004:11:26:43 -0700] "GET /VirtualHostBase/http/zwiki.org:80/InstallationGuide/editform HTTP/1.1" 200 15134 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [22/Jun/2004:11:26:59 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/PortalTransforms.encoding?view=src HTTP/1.1" 200 4505 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [22/Jun/2004:11:27:00 -0700] "GET /VirtualHostBase/http/www.zwiki.org:80/Chapter01WhatIsIt HTTP/1.1" 200 15435 "http://www.zwiki.org/FrontPage" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; .NET CLR 1.0.3705; .NET CLR 1.1.4322)"
 127.0.0.1 - Anonymous [22/Jun/2004:11:27:01 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/ZPublisher.xmlrpc?view=src HTTP/1.1" 200 16423 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [22/Jun/2004:11:27:02 -0700] "GET /VirtualHostBase/http/zwiki.org:80/HowToCustomizeZwikiSkins HTTP/1.1" 200 13554 "http://www.google.com.br/search?q=wikipage.pt&ie=UTF-8&hl=pt-BR&btnG=Pesquisa+Google&meta=" "Mozilla/5.0 (X11; U; Linux i686; pt-BR; rv:1.2.1) Gecko/20030225"
 127.0.0.1 - Anonymous [23/Jun/2004:09:21:46 -0700] "GET /VirtualHostBase/http/zwiki.org:80/robots.txt HTTP/1.1" 200 753 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"

The ZopeWiki:CheckZopeMem script is running on the server. Here is checkzopemem.log before & after hang:

 2004/06/22 11:23:01 PDT /zope1 process size: 84820
 2004/06/22 11:24:01 PDT /zope1 process size: 89836
 2004/06/22 11:25:02 PDT /zope1 process size: 90772
 2004/06/22 11:26:01 PDT /zope1 process size: 92660
 2004/06/22 11:27:01 PDT /zope1 process size: 92952
 2004/06/22 11:28:01 PDT /zope1 process size:
 2004/06/22 11:29:01 PDT /zope1 process size:
 2004/06/22 11:30:02 PDT /zope1 process size:
 2004/06/22 11:31:01 PDT /zope1 process size:


comments:

missing processes --SimonMichael, Tue, 29 Jun 2004 15:44:11 -0700 reply
Processes after hang:

  |-python,28903 /zope/lib/python/zdaemon/zdrun.py -S /zope/lib/python/ZEO/zeoctl.xml -C /zeo/etc/zeo.conf /zeo/bin/runzeo
  |   `-python,23381 /zope/lib/python/ZEO/runzeo.py -C /zeo/etc/zeo.conf
  |-python,9064 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf
  |-python,9120 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf

Healthy processes before hang (after a restart in this case):

  |-python,28903 /zope/lib/python/zdaemon/zdrun.py -S /zope/lib/python/ZEO/zeoctl.xml -C /zeo/etc/zeo.conf /zeo/bin/runzeo
  |   `-python,23381 /zope/lib/python/ZEO/runzeo.py -C /zeo/etc/zeo.conf
  |-python,32101 /zope/lib/python/zdaemon/zdrun.py -S /zope/lib/python/Zope/Startup/zopeschema.xml -b 10 -d -s...
  |   `-python,32102 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf
  |       `-python,32192 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf
  |           |-python,448 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf
  |           |-python,480 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf
  |           `-python,512 /zope/lib/python/Zope/Startup/run.py -C /zope1/etc/zope.conf

Looks like the zeo client is dying but not completely.

more data --simon, Thu, 01 Jul 2004 00:22:36 -0700 reply
More data.. see end..

Last minute of Z2.log:

 127.0.0.1 - Anonymous [30/Jun/2004:13:55:03 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/Shared.DC.ZRDB.__init__.html HTTP/1.1" 200 1351 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:14 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/ZODB.tests.IteratorStorage.html HTTP/1.1" 200 11581 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:18 -0700] "GET /VirtualHostBase/http/zwiki.org:80/Chapter03BasicUsage HTTP/1.1" 200 21796 "" "Mozilla/3.01 (compatible;)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:27 -0700] "GET /VirtualHostBase/http/zwiki.org:80/DTMLDocument/subscribeform HTTP/1.1" 200 3534 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:38 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/OptimisingZope HTTP/1.1" 404 1160 "" "ASPseek/1.2.10"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:44 -0700] "GET /VirtualHostBase/http/www.zwiki.org:80/WikiBadges/subscribeform HTTP/1.1" 200 3616 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:48 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/TAL.tests.run.html HTTP/1.1" 200 5015 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:48 -0700] "GET /VirtualHostBase/http/www.zwiki.org:80/IssueNo0531ShowingBugSeverityAndBugStatusOpenClosedInFreeformLinks HTTP/1.1" 200 13624 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:48 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/fileinput.html HTTP/1.1" 404 1335 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:55:56 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/AccessControl.tests.testUserFolder.html HTTP/1.1" 200 9332 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:56:04 -0700] "GET /VirtualHostBase/http/www.zwiki.org:80/IssueNo0658AddRealCommentsToIssuePropertyChanges/backlinks HTTP/1.1" 200 3411 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:56:04 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/ZODB.tests.TransactionalUndoVersionStorage.html HTTP/1.1" 200 6414 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 127.0.0.1 - Anonymous [30/Jun/2004:13:56:05 -0700] "GET /VirtualHostBase/http/zopewiki.org:80/zpydoc/docutils.nodes.Element.html HTTP/1.1" 200 5885 "" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"

Last and following minute of access.log:

 crawler15.googlebot.com - - [30/Jun/2004:13:55:03 -0700] "GET /zpydoc/Shared.DC.ZRDB.__init__.html HTTP/1.0" 200 1145 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler15.googlebot.com - - [30/Jun/2004:13:55:14 -0700] "GET /zpydoc/ZODB.tests.IteratorStorage.html HTTP/1.0" 200 11374 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler11.googlebot.com - - [30/Jun/2004:13:55:17 -0700] "GET /fs/epydoc/public/toc-CMFPlone.interfaces.InterfaceTool-module.html HTTP/1.0" 200 750 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 sea-proxy-ext.adobe.com - - [30/Jun/2004:13:55:18 -0700] "GET /Chapter03BasicUsage HTTP/1.1" 200 21589 "-" "Mozilla/3.01 (compatible;)"
 crawler14.googlebot.com - - [30/Jun/2004:13:55:22 -0700] "GET /fs/epydoc/private/TextIndexNG2.interfaces.IStopwords-module.html HTTP/1.0" 200 3282 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler11.googlebot.com - - [30/Jun/2004:13:55:26 -0700] "GET /fs/epydoc/private/mxmCounter-module.html HTTP/1.0" 200 4556 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler14.googlebot.com - - [30/Jun/2004:13:55:27 -0700] "GET /DTMLDocument/subscribeform HTTP/1.0" 200 3313 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler13.googlebot.com - - [30/Jun/2004:13:55:29 -0700] "GET /fs/epydoc/public/PlacelessTranslationService.TranslateTags-module.html HTTP/1.0" 200 6097 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler11.googlebot.com - - [30/Jun/2004:13:55:34 -0700] "GET /fs/epydoc/private/Formulator.DummyField-module.html HTTP/1.0" 200 5486 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 216-55-167-40.dedicated.abac.net - - [30/Jun/2004:13:55:38 -0700] "GET /OptimisingZope HTTP/1.0" 404 793 "-" "ASPseek/1.2.10"crawler11.googlebot.com - - [30/Jun/2004:13:55:38 -0700] "GET /fs/epydoc/public/TextIndexNG2.BaseParser-module.html HTTP/1.0" 200 4040 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler14.googlebot.com - - [30/Jun/2004:13:55:39 -0700] "GET /fs/epydoc/public/CMFCore.CookieCrumbler-module.html HTTP/1.0" 200 5360 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler10.googlebot.com - - [30/Jun/2004:13:55:44 -0700] "GET /WikiBadges/subscribeform HTTP/1.0" 200 3395 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler11.googlebot.com - - [30/Jun/2004:13:55:48 -0700] "GET /zpydoc/TAL.tests.run.html HTTP/1.0" 200 4809 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler14.googlebot.com - - [30/Jun/2004:13:55:48 -0700] "GET /zpydoc/fileinput.html HTTP/1.0" 404 968 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler10.googlebot.com - - [30/Jun/2004:13:55:48 -0700] "GET /IssueNo0531ShowingBugSeverityAndBugStatusOpenClosedInFreeformLinks HTTP/1.0" 200 13417 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler15.googlebot.com - - [30/Jun/2004:13:55:55 -0700] "GET /fs/epydoc/private/CMFCore.PortalObject-module.html HTTP/1.0" 200 5159 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler13.googlebot.com - - [30/Jun/2004:13:55:56 -0700] "GET /zpydoc/AccessControl.tests.testUserFolder.html HTTP/1.0" 200 9126 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler10.googlebot.com - - [30/Jun/2004:13:56:04 -0700] "GET /IssueNo0658AddRealCommentsToIssuePropertyChanges/backlinks HTTP/1.0" 200 3190 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler14.googlebot.com - - [30/Jun/2004:13:56:04 -0700] "GET /zpydoc/ZODB.tests.TransactionalUndoVersionStorage.html HTTP/1.0" 200 6208 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler10.googlebot.com - - [30/Jun/2004:13:56:04 -0700] "GET /fs/epydoc/private/Formulator.Widget.MultiItemsWidget-class.html HTTP/1.0" 200 11520 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler12.googlebot.com - - [30/Jun/2004:13:56:05 -0700] "GET /zpydoc/docutils.nodes.Element.html HTTP/1.0" 200 5679 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"

 crawler14.googlebot.com - - [30/Jun/2004:13:56:19 -0700] "GET /fs/epydoc/public/toc-transform.binding-module.html HTTP/1.0" 200 976 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler15.googlebot.com - - [30/Jun/2004:13:56:21 -0700] "GET /fs/epydoc/public/toc-TextIndexNG2.converters.StripTagParser-module.html HTTP/1.0" 200 987 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler13.googlebot.com - - [30/Jun/2004:13:56:23 -0700] "GET /fs/epydoc/public/CMFCore.WorkflowTool-module.html HTTP/1.0" 200 4923 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler11.googlebot.com - - [30/Jun/2004:13:56:26 -0700] "GET /fs/epydoc/public/transform.transforms.html4zope.Writer-class.html HTTP/1.0" 200 14518 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler15.googlebot.com - - [30/Jun/2004:13:56:33 -0700] "GET /fs/epydoc/public/toc-ZWiki.TESTLispG2-module.html HTTP/1.0" 200 886 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler14.googlebot.com - - [30/Jun/2004:13:56:33 -0700] "GET /fs/epydoc/public/ExtFile.ExtImage-module.html HTTP/1.0" 200 4746 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler14.googlebot.com - - [30/Jun/2004:13:56:33 -0700] "GET /fs/epydoc/public/ZWiki.Diff.DiffSupport-class.html HTTP/1.0" 200 12495 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler12.googlebot.com - - [30/Jun/2004:13:56:35 -0700] "GET /fs/epydoc/private/Formulator.TALESField.TALESNotAvailable-class.html HTTP/1.0" 200 4688 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler10.googlebot.com - - [30/Jun/2004:13:56:36 -0700] "GET /fs/epydoc/public/Formulator.Widget.MultiItemsWidget-class.html HTTP/1.0" 200 11521 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler15.googlebot.com - - [30/Jun/2004:13:56:37 -0700] "GET /fs/epydoc/public/CMFDeployment.ContentStorage-module.html HTTP/1.0" 200 5217 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"
 crawler11.googlebot.com - - [30/Jun/2004:13:56:42 -0700] "GET /fs/epydoc/private/transform.mime_types.text_plain-class.html HTTP/1.0" 200 45982 "-" "Googlebot/2.1 (+http://www.googlebot.com/bot.html)"

Last minute of zeo.log, level ALL:

 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4304, 0, zeoLoad, ('\x00\x00\x00\x00\x009e\xe1')
 ------
 2004-06-30T13:55:26 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x009e\xe1')
 ------
 2004-06-30T13:55:26 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc:3509 message_output 1857 bytes: "(I4304\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4305, 0, zeoLoad, ('\x00\x00\x00\x00\x009fj')
 ------
 2004-06-30T13:55:26 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x009fj')
 ------
 2004-06-30T13:55:26 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc:3509 message_output 2257 bytes: "(I4305\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4306, 0, zeoLoad, ('\x00\x00\x00\x00\x009kq')
 ------
 2004-06-30T13:55:47 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x009kq')
 ------
 2004-06-30T13:55:47 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc:3509 message_output 6052 bytes: "(I4306\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4307, 0, zeoLoad, ('\x00\x00\x00\x00\x009ku')
 ------
 2004-06-30T13:55:48 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x009ku')
 ------
 2004-06-30T13:55:48 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc:3509 message_output 3413 bytes: "(I4307\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4308, 0, zeoLoad, ('\x00\x00\x00\x00\x009ko')
 ------
 2004-06-30T13:55:48 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x009ko')
 ------
 2004-06-30T13:55:48 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc:3509 message_output 6552 bytes: "(I4308\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4309, 0, zeoLoad, ('\x00\x00\x00\x00\x00:gc')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x00:gc')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:3509 message_output 15701 bytes: "(I4309\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4310, 0, zeoLoad, ('\x00\x00\x00\x00\x00:gj')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x00:gj')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:3509 message_output 6523 bytes: "(I4310\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4311, 0, zeoLoad, ('\x00\x00\x00\x00\x00:gX')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x00:gX')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:3509 message_output 4854 bytes: "(I4311\nI0\nS'.reply'\n(S'((U\\x18Products.ZWiki.ZWikiP..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 recv msg: 4312, 0, zeoLoad, ('\x00\x00\x00\x00\x00A\xe9V')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 calling zeoLoad('\x00\x00\x00\x00\x00A\xe9V')
 ------
 2004-06-30T13:56:04 DEBUG(-200) zrpc-conn:127.0.0.1:48183 zeoLoad returns ('((U\x0eBTrees.OOBTreeq\x01U\x08OOBucketq\x02tq\x03Nt.((......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:3509 message_output 2225 bytes: "(I4312\nI0\nS'.reply'\n(S'((U\\x0eBTrees.OOBTreeq\\x01U..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:127.0.0.1:48183 poll(), async=1

Last minute of event.log, level ALL:

 2004-06-30T13:55:03 DEBUG(-200) Zpydoc __getitem__(Shared.DC.ZRDB.__init__)
 ------
 2004-06-30T13:55:13 DEBUG(-200) Zpydoc __getitem__(ZODB.tests.IteratorStorage)
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4304, 0, zeoLoad, ...
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc:21338 message_output 55 bytes: "(I4304\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x009e\..." hmac=0
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4304), async=0
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4304): asyncore.poll(0.001)
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4304): asyncore.poll(0.002)
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4304, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4304, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4304): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4305, 0, zeoLoad, ...
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4305\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x009fj..." hmac=0
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4305), async=0
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4305): asyncore.poll(0.001)
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4305): asyncore.poll(0.002)
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4305, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4305, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:26 TRACE(-300) zrpc-conn:localhost:9999 wait(4305): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4306, 0, zeoLoad, ...
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4306\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x009kq..." hmac=0
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 wait(4306), async=0
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 wait(4306): asyncore.poll(0.001)
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 wait(4306): asyncore.poll(0.002)
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 wait(4306): asyncore.poll(0.004)
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4306, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4306, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:47 TRACE(-300) zrpc-conn:localhost:9999 wait(4306): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:55:47 DEBUG(-200) Zpydoc __getitem__(TAL.tests.run)
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4307, 0, zeoLoad, ...
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4307\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x009ku..." hmac=0
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4307), async=0
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4307): asyncore.poll(0.001)
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4307): asyncore.poll(0.002)
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4307, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4307, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4307): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4308, 0, zeoLoad, ...
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4308\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x009ko..." hmac=0
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4308), async=0
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4308): asyncore.poll(0.001)
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4308): asyncore.poll(0.002)
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4308, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4308, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:55:48 TRACE(-300) zrpc-conn:localhost:9999 wait(4308): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:55:48 DEBUG(-200) Zpydoc __getitem__(fileinput)
 ------
 2004-06-30T13:55:56 DEBUG(-200) Zpydoc __getitem__(AccessControl.tests.testUserFolder)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4309, 0, zeoLoad, ...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4309\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x00:gc..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4309), async=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4309): asyncore.poll(0.001)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4309): asyncore.poll(0.002)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4309, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4309, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4309): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4310, 0, zeoLoad, ...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4310\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x00:gj..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4310), async=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4310): asyncore.poll(0.001)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4310): asyncore.poll(0.002)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4310): asyncore.poll(0.004)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4310, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4310, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4310): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4311, 0, zeoLoad, ...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:21338 message_output 52 bytes: "(I4311\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x00:gX..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4311), async=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4311): asyncore.poll(0.001)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4311): asyncore.poll(0.002)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4311, 0, .reply, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4311, 0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02tq......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4311): reply=(0, ('((U\x18Products.ZWiki.ZWikiPageq\x01U\tZWikiPageq\x02t...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 send msg: 4312, 0, zeoLoad, ...
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc:21338 message_output 55 bytes: "(I4312\nI0\nS'zeoLoad'\n(S'\\x00\\x00\\x00\\x00\\x00A\\..." hmac=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4312), async=0
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4312): asyncore.poll(0.001)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4312): asyncore.poll(0.002)
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv msg: 4312, 0, .reply, ('((U\x0eBTrees.OOBTreeq\x01U\x08OOBucketq\x02tq\x03Nt.((......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 recv reply: 4312, 0, ('((U\x0eBTrees.OOBTreeq\x01U\x08OOBucketq\x02tq\x03Nt.((......
 ------
 2004-06-30T13:56:04 TRACE(-300) zrpc-conn:localhost:9999 wait(4312): reply=(0, ('((U\x0eBTrees.OOBTreeq\x01U\x08OOBucketq\x02tq\x03Nt.(...
 ------
 2004-06-30T13:56:04 DEBUG(-200) Zpydoc __getitem__(ZODB.tests.TransactionalUndoVersionStorage)
 ------
 2004-06-30T13:56:05 DEBUG(-200) Zpydoc __getitem__(docutils.nodes.Element)
 ------
 2004-06-30T13:56:05 DEBUG(-200) Zpydoc __getitem__(AccessControl.tests.testSecurity)

The last shows the culprit. Apparently visiting certain Zpydoc pages causes the zope client to silently turn zombie (half-dead).

Oddly the AccessControl?.tests.testSecurity request does not appear in access.log, though docutils.nodes.Element does.

property change --simon, Thu, 01 Jul 2004 00:23:24 -0700 reply
Name: IssueNo0860 periodic zope hangs causing site outages => IssueNo0860 zpydoc causing periodic zope hangs

more detail --simon, Thu, 01 Jul 2004 02:46:53 -0700 reply
This is a python segfault; see PythonBug:983311 .

What to do ? Disable zpydoc, downgrade to python 2.3.3 (seems to work on a similar machine.. but how), disable that particular module in zpydoc (and which others..), beef up ZopeWiki:CheckZopeMem script to restart in this situation.. ?

property change --simon, Thu, 01 Jul 2004 02:58:59 -0700 reply
Name: IssueNo0860 zpydoc causing periodic zope hangs => IssueNo0860 zpydoc triggering zope hangs Category: general => zopewiki.org

disabled zpydoc --simon, Thu, 01 Jul 2004 03:48:32 -0700 reply
Zpydoc has been redirected to this page for now. This should stop the zope hangs.

ask last-bastion.org --d2m, Thu, 01 Jul 2004 04:04:18 -0700 reply
about how to exclude test folders from zpydoc

ask last-bastion.org --simon, Thu, 01 Jul 2004 04:31:46 -0700 reply
I don't know that this happens only in test modules. I'd have to check all zpydoc urls.

property change --simon, Mon, 05 Jul 2004 09:57:59 -0700 reply
Name: IssueNo0860 zpydoc triggering zope hangs => IssueNo0860 zpydoc triggering zope hangs/zpydoc unavailable

needs retesting & followup on python/zope trackers to progress --simon, Sun, 30 Jan 2005 16:31:36 -0800 reply
Category: site-zopewiki.org => other Severity: serious => normal