IRequestFilter - post_process_request() not called for errors in 0.11dev

[osimons <simon-code@…>]

(This ticket is really a follow-up to #3655, but as that was closed for milestone 0.10 I decided to create a new ticket for 0.11dev as 0.10 behavior is working fine.)

The additional data I need to render in all templates is currently added to the data dict through the post_process_request() method. However, if any 'early errors' (typically 404 or related to auth/permissions/access restrictions) occurs on request processing this method is not called - unlike the 'agreed' behavior in #3655 that modules should get a chance to add needed data to the returned data structure (then req.hdf, now data dictionary).

Genshi will produce a straight, white traceback page complaining (obviously) about UndefinedError for first occurance of one of my variable names.

Calls to post_process_request() needs to tried for any error occuring as early as the processing logic at trunk/trac/web/main.py@5748#L183​.

Two related notes from my testing:

• Actually, I get the same result for a typical internal error - like performing a search with only one character. A simple in-module error is raised, and a plain Genshi traceback is presented to users…
• Every now and then (can't quite locate the pattern), in my trac.log an additional error is produced from a my post-processor with TypeError: object does not support item assignment. This indicates to me that the data dict is in some (typically error) circumstances are passed as None type or similar, and not as an empty dict. The post-processors should be able to depend on the dict being initialised, so the dispatcher should perhaps call with argument data or {} or similar. Having all post-processors check for instance type and so on is bound to be error-prone.

[osimons <simon-code@…>]

Have been reading and testing the trac.web.main code to get something that works.

Conclusion: There is no way to make this work with current dispatch and error handling. Even where the post-processors are called correctly (not always obviously), it lacks mechanisms to actually pass the data dictionary over to rendering - the values returned are only ever caught and handled when the request is processed 'normally' (without any errors).

As it stands now, I suppose the only workaround is to start attaching my data dict to the req object, and work with req.data.myitem instead. The req object is the only thing that is certain from start to end, and obviously that is how 0.10 ensured that data always reached the templates regardless of what happened on the way (through req.hdf).

Hmm.. Would ideally like to just have one object for data from all modules. Could we 'sanction' an additional req.data structure that in template rendering gets added to the data dictionary (data.update(req.data))? Then it does not matter if you attach to one or the other - it will all just be data in the end…

[osimons <simon-code@…>]

Sorry, seems I somehow changed the milestone? It certainly was not my intention to shift it, and will leave release planning to others…

[osimons <simon-code@…>]

Patch that ensures that post_process_request() also gets called for 'early errors'. No side effects, I think.

[osimons <simon-code@…>]

I have uploaded a patch to attack this issue, and the patch is simple and really changes nothing - apart from giving post-processors a chance to get at the request object before anything renders to the user. I have tried to provoke various errors, but all error pages shown have evidence of being through my post-process filters (with the exception of the plain 'Environment not found' of course).

I have thought about the other part of this ticket; the fact that the return values from post-processors are always ignored. Post-processors return values, the caller silently ignores them. I am starting to think that is 'good enough' as long as at least the req object makes it to the handler. The only safe way to ensure that data or methods will always be available on rendering is to attach it to the req object - and with the patch that object is at least made available there.

The patch (or a variation thereof) makes the flow work ok. There are then ways to get things done using the APIs as they (mostly) should be used. With the patch, I think the ticket can be closed.

Lastly; I would be grateful to get this in for release 0.11.0. As I see it, there are a larger number of plugins that depend on getting hold of the req object before rendering. Custom visual, navigation and information elements that depend on data being available one way or another. Hacks like attaching objects to req while doing INavigationContributorshould not be necessary - especially when it has been working for 0.10.

[Christian Boos]

Patch looks mostly ok, except for the naming of the helper function (as it doesn't handle but instead raises an Exception).

It would also be interesting to have a way to let post-processer know that there's an error condition going on, so that they can eventually avoid to do some complex post-processing like making new SQL queries and so on.

[osimons <simon-code@…>]

Replying to cboos:

It would also be interesting to have a way to let post-processer know that there's an error condition going on, so that they can eventually avoid to do some complex post-processing like making new SQL queries and so on.

That was my original thought as well when we discussed this back at ticket:3655:12.

And, have found some errors that the patch does not manage to trap. It was an OperationalError(or similar) from my sqlite backend - database exceptions reached the user without me getting a chance to do anything about it. I have looked at trac.web.main but cannot figure out why. They just looks to be taking a different route back? Doesn't everything get trapped by the try: try: logic there?

[Noah Kantrowitz]

Can you please verify that this is still the case. I believe this was fixed a few weeks ago.

[osimons <simon-code@…>]

Nothing has changed in the source of main.py recently to resolve this. If there is a 404 (no handler) or permission error for instance, the post_process_request() will not be called.

Try a minimal plugin with a post-processor that just writes to log. It will not write entries for a number of 'early errors' + some other strange cases that I do not understand.

[ThurnerRupert]

is it a degression from 0.10, or this may go to 0.11.1?

[Christian Boos]

Somewhat different approach: the early errors use the same code path as other errors

[Christian Boos]

Clean-up of the dispatch_request function, where the environment was shut down too early

[Christian Boos]

Please have a look at attachment:post_process_early_errors-r6014.diff​ which takes a cleaner approach, I believe, as all the error post processing is done from the same place (look for "# post-process the request in case of errors").

Also, while reviewing that code, it occurred to me that in the dispatch_request function, we could shutdown the environment a bit later, after the rendering of the error.html template is done. It's not a really necessary change, as it appears that this rendering can't currently make use of neither of the db or the repository connections, but I think it's better that way. I put that optional change in a second patch: attachment:shutdown_after_error_processing-r6014.diff​

[osimons <simon-code@…>]

I have tested the patch, and it work well for all regular (and very common) 'early errors' like expected - trying just the first patch, and then also with the optional second patch:

• no handler found
• no permission

I provoked an Internal Error by introducing an error in a select statement in the wiki model (just to simulate some db error), but that does not get trapped and post-processed. I am still unable to figure out why. I'm sure this won't be a big deal in normal usage, but mostly curious as to why this isn't trapped and rendered like other errors?

My last comment is about the data dict, and a conclusion on usage. On errors the data dict is basically ignored, so for anyone needing data for template rendering also in error situations (custom header and footer fields for instance), it needs to be attached directly to the req object. This is how it needs to be, I suppose?

[Christian Boos]

Replying to osimons <simon-code@bvnetwork.no>:

I provoked an Internal Error by introducing an error in a select statement in the wiki model (just to simulate some db error), but that does not get trapped and post-processed.

worksforme… can you share your specific modification, maybe it's something special. For example, the following change simply triggers an OperationalError which gets correctly trapped, post-processed and rendered.

trac/wiki/model.py

@@ -47 +47 @@
             db = self.env.get_db_cnx()
         cursor = db.cursor()
         if version:
-            cursor.execute("SELECT version,time,author,text,comment,readonly "
+            cursor.execute("SEL ECT version,time,author,text,comment,readonly "
                            "FROM wiki "
                            "WHERE name=%s AND version=%s",
                            (name, int(version)))

My last comment is about the data dict, and a conclusion on usage. On errors the data dict is basically ignored, so for anyone needing data for template rendering also in error situations (custom header and footer fields for instance), it needs to be attached directly to the req object.

if we would pass the data dict from post-processors to error rendering, then the 2^nd patch is even more important, because data could contain anything, including db, in which case it is important that the shutdown comes only after db gets used.

[osimons <simon-code@…>]

Replying to cboos:

worksforme… can you share your specific modification, maybe it's something special. For example, the following change simply triggers an OperationalError which gets correctly trapped, post-processed and rendered.

Further research, and you are (as always) right in that the post-processor does get called - and most things are actually there. However, I have been visually tricked by the fact that this does not work - and my stylesheets does not get added (example mini-implementation):

    def post_process_request(self, req, template, data, content_type):
        add_stylesheet(req, 'site/css/mystyles.css')
        return (template, data, content_type)

So the operational error (like yours above) will render with trac.css stylesheet only.

[Christian Boos]

See r4114.

[osimons <simon-code@…>]

I commented out the lines from r4114, and it all works like a charm - the SEL ECT imaginary error displays just like my other errors, but this time with a traceback of course. Printed some debug from req.chrome from the erronous request, and it all looks intact and as it should be. Certainly my error page visually looks just like I wanted it to.

I have trouble seeing the argumentation for why req.chrome should be deleted in case of errors? It contains links to some meta-information such as htdocs location and icon, stylesheets, navigation items and script files. With the current implementation req.chrome isn't really empty (deleted) when rendering the error page, because the chrome data for Operational Error contains everything except my stylesheets (and my javascript file)?

Why can't my links information survive for rendering internal error when they're already added?

[osimons <simon-code@…>]

Some more notes on del req.chrome:

Chatted with cmlenz, and he located the orginal introduction of the delete - see [4101] #file19. There is no documented reason in that changeset, but he seemed to recall it had something to do with late_links / late_scripts stuff.

Now, deleting these 4 lines is not strictly a matter for this ticket, and should not hold back committing the other tested patches that seems to work fine. However, if the 4 lines where to be included it will help clean up the whole error-rendering cycle for plugins - I have not managed to provoke any situation where they make any meaning, and their presence will be a constant issue for any plugin implementing styles/themes. I'll take full responsibility :-)

[Christian Boos]

Fixed in r6125, r6126.

Clean-up patch attachment:shutdown_after_error_processing-r6014.diff​ also applied in r6127.

[Christian Boos]

Replying to osimons <simon-code@bvnetwork.no>:

Some more notes on del req.chrome:

Chatted with cmlenz, and he located the orginal introduction of the delete - see [4101] #file19. There is no documented reason in that changeset, but he seemed to recall it had something to do with late_links / late_scripts stuff.

Indeed :-) See r6135 "for the gory details".