Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix edge case in exception handler causing recursion #260

Merged

Conversation

MatthewWilkes
Copy link
Contributor

@MatthewWilkes MatthewWilkes commented May 7, 2018

During Plone's porting efforts to Python 3.6 a bug was found
that caused Python to dump core with a stack overflow. This
is caused in the field handling, where a template calls a
macro which then inserts the rendered body of another pagetemplate.

The inner page template is rendered and calls the exception handler
correctly, which causes the exception's __str__ method to be
replaced with an instance of ExceptionFormatter. However, as
this is within a macro the visit_Macro function causes that
exception to be added to rcontext['__error__'], meaning that
when the outer template attempts to format its exception the
handling of the __errors__ list causes recursion into the
ExceptionFormatter until the maximum recursion depth is reached
at which point the error handling is aborted as unformattable
by the traceback module in the standard library.

If the exception is sufficiently large it smashes the stack before
this can happen, causing a core dump. If it isn't sufficiently
large a confusingly repetitious error is shown.

During Plone's porting efforts to Python 3.6 a bug was found
that caused Python to dump core with a stack overflow. This
is caused in the field handling, where a template calls a
macro which then inserts the rendered body of another pagetemplate.

The inner page template is rendered and calls the exception handler
correctly, which causes the exception's `__str__` method to be
replaced with an instance of `ExceptionFormatter`. However, as
this is within a macro the `visit_Macro` function causes that
exception to be added to `rcontext['__error__']``, meaning that
when the outer template attempts to format its exception the
handling of the `__errors__` list causes recursion into the
`ExceptionFormatter` until the maximum recursion depth is reached
at which point the error handling is aborted as unformattable
by the traceback module in the standard library.

If the exception is sufficiently large it smashes the stack before
this can happen, causing a core dump. If it isn't sufficiently
large a confusingly repetitious error is shown.
@MatthewWilkes
Copy link
Contributor Author

This is intended to fix plone/Products.CMFPlone#2370

@malthe
Copy link
Owner

malthe commented May 7, 2018

There's been something fishy about the rendering of nested errors for some time – this looks good, but I have one question: does it work in practice on "normal" template errors...?

Because I find that the output just often times makes no sense – and it used to!

@gp54321
Copy link

gp54321 commented May 7, 2018

I reported on this bug in the linked Plone issue.
To test the PR I added back to (more or less) current Plone 5.2 with Chameleon an 'innocuous' bug (divide by zero like said in my original post in the linked issue) and Plone crashed 'normally' (backtrace divide by zero) and crashed 'hard' (coredump) on the carefully wrong data I had entered in a rich text field.

With the patch added to Chamelon 3.2, I got a nice backtrace instead of the coredump (that's expected behavior since the data is totally incorrect) and the same backtrace for the more 'normal' template bug (divide by zero) so it's complete success for me.

Here is the backtrace for the 'normal' exception:

Traceback (innermost last):
  Module ZPublisher.WSGIPublisher, line 127, in transaction_pubevents
  Module ZPublisher.WSGIPublisher, line 256, in publish_module
  Module ZPublisher.WSGIPublisher, line 209, in publish
  Module ZPublisher.mapply, line 85, in mapply
  Module ZPublisher.WSGIPublisher, line 56, in call_object
  Module five.customerize.zpt, line 83, in __call__
  Module Products.PageTemplates.ZopePageTemplate, line 272, in _exec
  Module Products.PageTemplates.ZopePageTemplate, line 354, in pt_render
  Module Products.PageTemplates.PageTemplate, line 83, in pt_render
  Module zope.pagetemplate.pagetemplate, line 134, in pt_render
  Module Products.PageTemplates.engine, line 85, in __call__
  Module z3c.pt.pagetemplate, line 158, in render
  Module chameleon.zpt.template, line 297, in render
  Module chameleon.template, line 191, in render
  Module chameleon.utils, line 75, in raise_with_traceback
  Module chameleon.template, line 171, in render
  Module 5b39dbfdf55be66bf5538db6c84ece3f.py, line 243, in render
  Module f43aed57eabc66564ab51346e4cb5bf1.py, line 682, in render_master
  Module f43aed57eabc66564ab51346e4cb5bf1.py, line 1307, in render_content
  Module 5b39dbfdf55be66bf5538db6c84ece3f.py, line 161, in __fill_main
ZeroDivisionError: division by zero

 - Expression: "provider:plone.abovecontent"
 - Filename:   ... one/Products/CMFPlone/browser/templates/main_template.pt
 - Location:   (line 67: col 59)
 - Source:     ... 
                                       ^
 - Expression: "context/main_template/macros/master"
 - Filename:   /Plone/zope.interface.interface-sitemap
 - Location:   (line 6: col 23)
 - Arguments:  template: <ImplicitAcquisitionWrapper zope.interface.interface-sitemap at 0x7f9a8487f630>
               here: <ImplicitAcquisitionWrapper Plone at 0x7f9a84765708>
               context: <ImplicitAcquisitionWrapper Plone at 0x7f9a84765708>
               container: <ImplicitAcquisitionWrapper Plone at 0x7f9a84765708>
               nothing: <NoneType - at 0x9dfba0>
               options: {...} (1)
               root: <ImplicitAcquisitionWrapper  at 0x7f9a847658b8>
               request: <WSGIRequest - at 0x7f9a853b78d0>
               modules: <_SecureModuleImporter - at 0x7f9a8aa64d68>
               view: <TTWView None at 0x7f9a81283860>
               user: <ImplicitAcquisitionWrapper - at 0x7f9a8487f750>
               default: <object - at 0x7f9a914878f0>
               repeat: {...} (0)
               loop: {...} (0)
               wrapped_repeat: <SafeMapping - at 0x7f9a81213108>
               target_language: <NoneType - at 0x9dfba0>
               translate: <function translate at 0x7f9a83a719d8>
               macroname: master

The raise_with_traceback line in the middle of the trace is of course not what could be seen in a debugger if one was setting a breakpoint at the exception point. Not a big problem IMO.

@MatthewWilkes
Copy link
Contributor Author

I guarded the change with a check to see if __str__ is the ExceptionFormatter, where it follows the normal code path if it isn't. I tried a few things to reproduce this error and the only way I could find to do it was by nesting page templates.

Perhaps the issue with the normal errors is that the formatted error is always based on rcontent['errors'] rather than the raised exception, so they might be getting out of sync if there are multiple macros involved.

If you look at the Plone issue linked the error passes through an unrelated looking tal:condition in the context, which looks bogus to me. I'll have a look at the error handling in general, but I don't think this patch affects the general case.

@MatthewWilkes
Copy link
Contributor Author

@malthe I've done some poking, and from a first approximation I think that setting __token = None as the first thing in the UseInternalMacro visitor greatly improves error messages. It looks to me like the poor quality is because of spurious context, as metal macros that aren't overridden are handled in a function scope without a token boundary being crossed. This means that there are additional context entries added which do not make much sense to users but more critically are misreported as being caused by the previous TALES expression.

@MatthewWilkes
Copy link
Contributor Author

By way of comparison, the following change:

index 7d2986d..cff68d3 100644
--- a/src/chameleon/compiler.py
+++ b/src/chameleon/compiler.py
@@ -1493,8 +1493,8 @@ class Compiler(object):
             render = "render"
         else:
             render = "render_%s" % mangle(node.name)
-
-        return template(
+        token_reset = template("__token = None")
+        return token_reset + template(
             "f(__stream, econtext.copy(), rcontext, __i18n_domain)",
             f=render) + \
             template("econtext.update(rcontext)")

means the error:


 - Expression: "widget/render"
 - Filename:   ... /plone.app.z3cform/plone/app/z3cform/templates/widget.pt
 - Location:   (line 39: col 46)
 - Source:     ... xt" tal:replace="structure widget/render"
                                              ^^^^^^^^^^^^^
 - Expression: "widget/@@ploneform-render-widget"
 - Filename:   ... /plone.app.z3cform/plone/app/z3cform/templates/macros.pt
 - Location:   (line 100: col 81)
 - Source:     ... place="structure widget/@@ploneform-render-widget"/>
                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 - Expression: "view/widgets/values"
 - Filename:   ... /plone.app.z3cform/plone/app/z3cform/templates/macros.pt
 - Location:   (line 97: col 62)
 - Source:     ... :widgets repeat="widget view/widgets/values">
                                           ^^^^^^^^^^^^^^^^^^^
 - Expression: "default_fieldset_label"
 - Filename:   ... /plone.app.z3cform/plone/app/z3cform/templates/macros.pt
 - Location:   (line 94: col 51)
 - Source:     tal:content="default_fieldset_label">Form name</legend>
                            ^^^^^^^^^^^^^^^^^^^^^^
 - Expression: "python:has_groups and enable_form_tabbing and current_fieldset is not None"
 - Filename:   ... /plone.app.z3cform/plone/app/z3cform/templates/macros.pt
 - Location:   (line 80: col 41)
 - Source:     ... python:has_groups and enable_form_tabbing and current_fieldset is not None ...
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 - Expression: "context/@@ploneform-macros/titlelessform"
 - Filename:   ... plone.z3cform/src/plone/z3cform/templates/wrappedform.pt
 - Location:   (line 1: col 22)
 - Source:     ... e use-macro="context/@@ploneform-macros/titlelessform" />
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 - Arguments:  template: <ViewPageTemplateFile - at 0x7f51efd34ba8>
               options: {...} (0)
               args: <tuple - at 0x7f51fd79e048>
               nothing: <NoneType - at 0x9dfba0>
               modules: <TraversableModuleImporter - at 0x7f51f5809518>
               request: <WSGIRequest - at 0x7f51ef390b00>
               view: <RenderWidget ploneform-render-widget at 0x7f51ef9accf8>
               context: <RichTextWidget IRichText.text at 0x7f51efbde8d0>
               views: <ViewMapper - at 0x7f51ee43a5f8>
               default: <object - at 0x7f51fd7998f0>
               repeat: {...} (0)
               loop: {...} (0)
               wrapped_repeat: {...} (0)
               target_language: <NoneType - at 0x9dfba0>
               translate: <function translate at 0x7f51ef694c80>

becomes


 - Expression: "widget/@@ploneform-render-widget"
 - Filename:   ... /plone.app.z3cform/plone/app/z3cform/templates/macros.pt
 - Location:   (line 100: col 81)
 - Source:     ... place="structure widget/@@ploneform-render-widget"/>
                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 - Expression: "context/@@ploneform-macros/titlelessform"
 - Filename:   ... plone.z3cform/src/plone/z3cform/templates/wrappedform.pt
 - Location:   (line 1: col 22)
 - Source:     ... e use-macro="context/@@ploneform-macros/titlelessform" />
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 - Arguments:  template: <ViewPageTemplateFile - at 0x7fd9310b1358>
               options: {...} (0)
               args: <tuple - at 0x7fd93eac6048>
               nothing: <NoneType - at 0x9dfba0>
               modules: <TraversableModuleImporter - at 0x7fd936b314a8>
               request: <WSGIRequest - at 0x7fd9326d5390>
               view: <DefaultEditForm edit at 0x7fd9326f12b0>
               context: <ImplicitAcquisitionWrapper front-page at 0x7fd9325b0288>
               views: <ViewMapper - at 0x7fd932b53e10>
               default: <object - at 0x7fd93eac18f0>
               repeat: {...} (0)
               loop: {...} (1)
               wrapped_repeat: {...} (1)
               target_language: <NoneType - at 0x9dfba0>
               translate: <function translate at 0x7fd93313abf8>
               macroname: titlelessform```

@malthe
Copy link
Owner

malthe commented May 8, 2018

I think that token fix looks about right then – it's something that I recently added, to reduce cost of the high-level "try/except" blocks. Now, Chameleon just assigns a single error token to a predefined global value.

@malthe malthe merged commit d244c49 into malthe:master May 8, 2018
malthe added a commit that referenced this pull request May 8, 2018
malthe added a commit that referenced this pull request May 8, 2018
@malthe
Copy link
Owner

malthe commented May 8, 2018

PR here for your token fix: #261.

jensens added a commit to zopefoundation/Zope that referenced this pull request Aug 10, 2018
this version contains a fix for malthe/chameleon#260
icemac pushed a commit to zopefoundation/Zope that referenced this pull request Aug 17, 2018
this version contains a fix for malthe/chameleon#260
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants