Plone deadlock when handling a handful of POST requests in quick succession

[neilferreira]

Hi all

I'm having issues with one of my Plone websites at the moment where the entire Plone instance will deadlock and need to be restarted if I hit "submit" on one of my forms in quick succession, say 10 times.

The Plone processes take up 100% cpu and the website becomes unresponsive. In a controlled environment I've installed the slow request logger which seems to pin-point the issue to code being run in this package. Has anyone run into something like this before?

This backtrace is printed out over-and-over every few seconds

2016-04-19 15:30:01,238 - Thread 139954733217536: Started on 1461050501.3; Running for 499.9 secs; [No request]
Traceback:
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZServer/PubCore/ZServerPublisher.py", line 31, in __init__
    response=b)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 455, in publish_module
    environ, debug, request, response)
  File "/home/plone/eggs/Products.LongRequestLogger-1.1.0-py2.7.egg/Products/LongRequestLogger/patch.py", line 16, in wrapper
    result = wrapper.original(*args, **kw)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 249, in publish_module_standard
    response = publish(request, module_name, after_list, debug=debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 207, in publish
    return publish(newrequest, module_name, after_list, debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 207, in publish
    return publish(newrequest, module_name, after_list, debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 207, in publish
    return publish(newrequest, module_name, after_list, debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 191, in publish
    notify(PubBeforeAbort(request, exc_info, retry))
  File "/home/plone/eggs/zope.event-3.5.2-py2.7.egg/zope/event/__init__.py", line 31, in notify
    subscriber(event)
  File "/home/plone/eggs/zope.component-3.9.5-py2.7.egg/zope/component/event.py", line 24, in dispatch
    zope.component.subscribers(event, None)
  File "/home/plone/eggs/zope.component-3.9.5-py2.7.egg/zope/component/_api.py", line 136, in subscribers
    return sitemanager.subscribers(objects, interface)
  File "/home/plone/eggs/zope.component-3.9.5-py2.7.egg/zope/component/registry.py", line 321, in subscribers
    return self.adapters.subscribers(objects, provided)
  File "/home/plone/eggs/zope.interface-3.6.7-py2.7-linux-x86_64.egg/zope/interface/adapter.py", line 585, in subscribers
    subscription(*objects)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/zpublisher.py", line 119, in applyTransformOnFailure
    applyTransformOnSuccess(event)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/zpublisher.py", line 79, in applyTransformOnSuccess
    transformed = applyTransform(event.request)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/zpublisher.py", line 69, in applyTransform
    transformed = transformer(request, result, encoding)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/transformer.py", line 48, in __call__
    newResult = handler.transformIterable(result, encoding)
  File "/home/plone/eggs/plone.app.theming-1.1.1-py2.7.egg/plone/app/theming/transform.py", line 181, in transformIterable
    transformed = transform(result.tree, **params)

2016-04-19 15:30:03,262 - Thread 139954724824832: Started on 1461050501.3; Running for 501.9 secs; [No request]
Traceback:
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZServer/PubCore/ZServerPublisher.py", line 31, in __init__
    response=b)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 455, in publish_module
    environ, debug, request, response)
  File "/home/plone/eggs/Products.LongRequestLogger-1.1.0-py2.7.egg/Products/LongRequestLogger/patch.py", line 16, in wrapper
    result = wrapper.original(*args, **kw)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 249, in publish_module_standard
    response = publish(request, module_name, after_list, debug=debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 207, in publish
    return publish(newrequest, module_name, after_list, debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 207, in publish
    return publish(newrequest, module_name, after_list, debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 207, in publish
    return publish(newrequest, module_name, after_list, debug)
  File "/home/plone/eggs/Zope2-2.13.22-py2.7.egg/ZPublisher/Publish.py", line 191, in publish
    notify(PubBeforeAbort(request, exc_info, retry))
  File "/home/plone/eggs/zope.event-3.5.2-py2.7.egg/zope/event/__init__.py", line 31, in notify
    subscriber(event)
  File "/home/plone/eggs/zope.component-3.9.5-py2.7.egg/zope/component/event.py", line 24, in dispatch
    zope.component.subscribers(event, None)
  File "/home/plone/eggs/zope.component-3.9.5-py2.7.egg/zope/component/_api.py", line 136, in subscribers
    return sitemanager.subscribers(objects, interface)
  File "/home/plone/eggs/zope.component-3.9.5-py2.7.egg/zope/component/registry.py", line 321, in subscribers
    return self.adapters.subscribers(objects, provided)
  File "/home/plone/eggs/zope.interface-3.6.7-py2.7-linux-x86_64.egg/zope/interface/adapter.py", line 585, in subscribers
    subscription(*objects)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/zpublisher.py", line 119, in applyTransformOnFailure
    applyTransformOnSuccess(event)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/zpublisher.py", line 79, in applyTransformOnSuccess
    transformed = applyTransform(event.request)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/zpublisher.py", line 69, in applyTransform
    transformed = transformer(request, result, encoding)
  File "/home/plone/eggs/plone.transformchain-1.0.3-py2.7.egg/plone/transformchain/transformer.py", line 48, in __call__
    newResult = handler.transformIterable(result, encoding)
  File "/home/plone/eggs/plone.app.theming-1.1.1-py2.7.egg/plone/app/theming/transform.py", line 181, in transformIterable
    transformed = transform(result.tree, **params)

[vangheem]

In my experience, deadlocks are most often caused by your plone system doing another request inside an existing request.

For example, you request http://foo.com/page. The rendering of http://foo.com/page requires one thread; however, an internal request is made during that rendering which requires another thread in order to finish.

So the deadlock happens when the total number of active requests is greater than the total number of threads you have running your server.

In this case with plone.app.theming, I'd be interested in looking at your theme file. Do you enable external resource inclusion rules that actually just go to the same plone client perhaps? Are you able to share your rules file?

[djowett]

@neilferreira I saw a similar stacktrace for an issue with plone.app.debugtoolbar. As it turned out there, plone.app.theming was not the culprit. Obviously you might not be using plone.app.debugtoolbar, but if so then you could try disabling it.

plone/plone.app.debugtoolbar#13