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

Emit all errors in hooks #1806

Merged
merged 9 commits into from
Oct 2, 2019
Merged

Conversation

jaraco
Copy link
Member

@jaraco jaraco commented Sep 10, 2019

What kind of change does this PR introduce?

  • bug fix
  • feature
  • docs update
  • tests/coverage improvement
  • refactoring
  • other

What is the related issue number (starting with #)

#1770

Other information:

This alternative implementation is based on the one I proposed in #1771. It uses recursion and the exception handling inherent to Python to emit multiple tracebacks. This works because

  • The run_hooks method receives an iterable, so whatever is in hooks during the recursive call are the hooks that have not yet run.
  • The failsafe hooks are selected to be run recursively. Again, this relies on the lazy evaluation of hooks.
  • When the last exception raises and there are no more hooks to be run, Python 3 should emit all of the exceptions in the order in which they were encountered.

Checklist:

  • I think the code is well written
  • I wrote good commit messages
  • I have squashed related commits together after the changes have been approved
  • Unit tests for the changes exist
  • Integration tests for the changes exist (if applicable)
  • I used the same coding conventions as the rest of the project
  • The new code doesn't generate linter offenses
  • Documentation reflects the changes
  • The PR relates to only one subject with a clear title
    and description in grammatically correct, complete sentences

@webknjaz
Copy link
Member

@jaraco only changelog shows up in the PR diff. Did you forget to commit something?

@jaraco jaraco force-pushed the feature/1770-log-all-errors-in-hooks branch from f22c70d to 0cf207c Compare September 10, 2019 17:03
@jaraco jaraco closed this Sep 10, 2019
@jaraco jaraco reopened this Sep 10, 2019
@codecov

This comment has been minimized.

@jaraco
Copy link
Member Author

jaraco commented Sep 10, 2019

I started this work in maint/17.x as it was requested to be included in the 17.x line, but I realized that the benefits only apply to Python 3 anyway, so I'm proposing merging this only to master.

CHANGES.rst Outdated Show resolved Hide resolved
try:
hook()
except quiet_errors:
cls.run_hooks(safe)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is hard to follow the control flow with this recursive iterator shrinking.
Any ideas on how to improve the readability here?

Also, I'd maybe create a partial out of this before the loop to better communicate the intent:

run_rest_of_safe_hooks = functools.partial(cls.run_hooks, safe)  # Will not enter an infinite loop because it's bound to the same iterator and the loop in the previous invocation on stack consumes failed callbacks.

Is there any way to avoid recursion? This looks like a case for TCO.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can't think of a way without recursion to (a) catch an exception and (b) within the caught exception resume processing.

I agree it's hard to read; there's a lot going on in just a few lines, and it's incorporating a lot of rarely incorporated language features.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can work on refining the implementation.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The current implementation will create an exception chain whether they'll be "causes" of one another which is not exactly true and may be misleading.
Other way to do this is to chain exceptions manually setting the previous ones as exc.__reason__. The only difference would be a text message saying that the previous exception is the cause of the current one as opposed to saying that the previous exception happened while handling the current one.
Would this help?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure these exceptions should be chained at all. They are all somewhat independent errors... their common thread is that they're part of the same hooks on the same request. That is, I don't think they're associated as "reason for exception X is exception Y", so __reason__ doesn't sound like the right approach.

Co-Authored-By: Sviatoslav Sydorenko <wk@sydorenko.org.ua>
@jaraco
Copy link
Member Author

jaraco commented Sep 11, 2019

Also, I should have said that I haven't tested this other than to run the cherrypy tests. I think this behavior deserves at least a demonstration that it achieves the desired behavior, even if it's not part of a unit test.

@jaraco
Copy link
Member Author

jaraco commented Sep 11, 2019

I don't understand why the tests are failing. They pass for me locally. I think there's something configured in Travis to cause warnings as errors. I'm not sure where that is.

@jaraco
Copy link
Member Author

jaraco commented Sep 11, 2019

Oh, maybe it was that tests were passing on the maint/17.x branch. I hadn't tested since merging with master.

@jaraco
Copy link
Member Author

jaraco commented Sep 11, 2019

Right, so I see filterwarnings = error. That would make warnings raise exceptions. My guess is that these exceptions that were previously being suppressed are now getting raised. I think that's a sign that this code is working as intended... but we need to fix the deprecation warnings in master first.

@jaraco
Copy link
Member Author

jaraco commented Sep 11, 2019

On further consideration, I see that the error was actually in the new code, with the check for collections.Iterator. After correcting that, I see tests passing now.

@jaraco
Copy link
Member Author

jaraco commented Oct 2, 2019

I think this behavior deserves at least a demonstration that it achieves the desired behavior, even if it's not part of a unit test.

I created this repro, which if run on master, produces:

~ $ http localhost:8080                                                                                                                      
HTTP/1.1 500 Internal Server Error
Content-Length: 1608
Content-Type: text/html;charset=utf-8
Date: Wed, 02 Oct 2019 23:34:19 GMT
Server: CherryPy/18.2.1.dev13+gf4d261f4

<!DOCTYPE html PUBLIC
"-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html>
<head>
    <meta http-equiv="Content-Type" content="text/html; charset=utf-8"></meta>
    <title>500 Internal Server Error</title>
    <style type="text/css">
    #powered_by {
        margin-top: 20px;
        border-top: 2px solid black;
        font-style: italic;
    }

    #traceback {
        color: red;
    }
    </style>
</head>
    <body>
        <h2>500 Internal Server Error</h2>
        <p>The server encountered an unexpected condition which prevented it from fulfilling the request.</p>
        <pre id="traceback">Traceback (most recent call last):
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 628, in respond
    self._do_respond(path_info)
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 691, in _do_respond
    self.hooks.run('before_finalize')
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 114, in run
    raise exc
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 104, in run
    hook()
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 63, in __call__
    return self.callback(**self.kwargs)
  File "test-1770.py", line 11, in noisy_hook_2
    raise ValueError('hook 2 failed')
ValueError: hook 2 failed
</pre>
    <div id="powered_by">
      <span>
        Powered by <a href="http://www.cherrypy.org">CherryPy 18.2.1.dev13+gf4d261f4</a>
      </span>
    </div>
    </body>
</html>

whereas with the patch applied, the result includes both exceptions that occurred:

~ $ http localhost:8080                                                                                                                      
HTTP/1.1 500 Internal Server Error
Content-Length: 2234
Content-Type: text/html;charset=utf-8
Date: Wed, 02 Oct 2019 23:33:53 GMT
Server: CherryPy/18.2.1.dev13+gf4d261f4

<!DOCTYPE html PUBLIC
"-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html>
<head>
    <meta http-equiv="Content-Type" content="text/html; charset=utf-8"></meta>
    <title>500 Internal Server Error</title>
    <style type="text/css">
    #powered_by {
        margin-top: 20px;
        border-top: 2px solid black;
        font-style: italic;
    }

    #traceback {
        color: red;
    }
    </style>
</head>
    <body>
        <h2>500 Internal Server Error</h2>
        <p>The server encountered an unexpected condition which prevented it from fulfilling the request.</p>
        <pre id="traceback">Traceback (most recent call last):
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 117, in run_hooks
    hook()
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 65, in __call__
    return self.callback(**self.kwargs)
  File "test-1770.py", line 6, in noisy_hook_1
    raise ValueError('hook 1 failed')
ValueError: hook 1 failed

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 638, in respond
    self._do_respond(path_info)
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 701, in _do_respond
    self.hooks.run('before_finalize')
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 95, in run
    self.run_hooks(iter(sorted(self[point])))
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 123, in run_hooks
    cls.run_hooks(safe)
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 117, in run_hooks
    hook()
  File "/Users/jaraco/code/public/cherrypy/cherrypy/cherrypy/_cprequest.py", line 65, in __call__
    return self.callback(**self.kwargs)
  File "test-1770.py", line 11, in noisy_hook_2
    raise ValueError('hook 2 failed')
ValueError: hook 2 failed
</pre>
    <div id="powered_by">
      <span>
        Powered by <a href="http://www.cherrypy.org">CherryPy 18.2.1.dev13+gf4d261f4</a>
      </span>
    </div>
    </body>
</html>

I believe this effectively demonstrates the effectiveness of the change.

Because this relies on Python 3 to achieve its ends, I'm not going to attempt to back port this to 17.x, although I welcome others to try.

@jaraco jaraco merged commit f185ecd into master Oct 2, 2019
@jaraco jaraco deleted the feature/1770-log-all-errors-in-hooks branch October 2, 2019 23:40
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.

2 participants