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

[9410] Don't throw KeyError exception on write to _disconnected http request #1106

Merged
merged 14 commits into from May 17, 2019

Conversation

jswitzer
Copy link
Contributor

Instead, discard the data, and throw the usual RuntimeError exception on request.finish.

This is really a compatibility fix - Twisted version 15.4 used to behave this way. I think some of the changes around queuing mode modified the behavior to throw a KeyError instead (see the Trac issue for more details).

Contributor Checklist:

@glyph
Copy link
Member

glyph commented Feb 27, 2019

Hi! Thanks for your effort to fix this bug. It’s super annoying and I can’t wait to squash it :). But it seems like there are lots of test failures that result from this change. Can you fix them up by any chance? Thanks!

@jswitzer
Copy link
Contributor Author

Sounds good - I'll take a look at those failures and update the PR once they pass

@codecov
Copy link

codecov bot commented Feb 27, 2019

Codecov Report

Merging #1106 into trunk will decrease coverage by 0.36%.
The diff coverage is 90.9%.

@@            Coverage Diff             @@
##            trunk    #1106      +/-   ##
==========================================
- Coverage   91.99%   91.62%   -0.37%     
==========================================
  Files         844      845       +1     
  Lines      151096   151165      +69     
  Branches    13161    13182      +21     
==========================================
- Hits       138994   138505     -489     
- Misses      10003    10534     +531     
- Partials     2099     2126      +27

@jswitzer
Copy link
Contributor Author

The tests are passing now - I just needed to update one http2 test to not expect an AttributeError Exception to be to thrown on a write after the request went into _disconnected; that test was written after the behavior change. I did some grepping for AttributeErrors in twisted/web, and I'm reasonably confident nothing else is expecting that exception to be thrown.

I don't see any build corresponding to this PR on https://buildbot.twistedmatrix.com/buildslaves/egh-osx-1, so I'm not sure why the build is hanging. Should this have gone to another buildbot instance - or is this something that can be ignored?

@glyph
Copy link
Member

glyph commented Apr 20, 2019

@jswitzer FYI, your email address is set incorrectly in your commits. I can run a script (https://help.github.com/en/articles/changing-author-info) to fix this up before landing this PR, so you'll be appropriately credited, but you should probably fix your local git configuration for future changes.

(You can tell because the commits you made locally have a blank octocat icon, rather than your profile picture.)

src/twisted/web/test/test_http.py Outdated Show resolved Hide resolved
self.assertRaises(AttributeError, request.write, b"third chunk")
# This should not raise an exception, the function will just return
# immediately, and do nothing
request.write(b"third chunk")
Copy link
Member

Choose a reason for hiding this comment

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

Hmm. So this is actually a tested behavior of a public interface being changed... 🤔

Although, jeez, AttributeError? That's a pretty sad behavior. I expect whoever wrote this test just encoded whatever accidental implementation behavior they happened to get without thinking about it very hard.

Yet, regardless of that, it's still a tested behavior of a public interface. Strictly speaking, this is a backwards incompatible change (what if someone wrote an application that depends on AttributeError here to notice a closed connection?).

Ignoring backward compatibility concerns, I'd probably go along with this new behavior as sensible, but I don't think we get to ignore those concerns. Unless... considering people are complaining about this behavior after upgrading, it could be the exception behavior is relatively new and was introduced accidentally as part of some other work?

The "safe" thing for me to say is that this fix needs to be inside the wsgi implementation instead of inside the IRequest implementation. If we knew exactly when the exception behavior was introduced, maybe we could make a different decision.

And, with a little help from git bisect, I see that ticket:8191 is where the change was introduced and it was first released in 16.3.0. That's annoyingly long ago. Does it mean the new behavior has to be considered the intended behavior and compatibility needs to be maintained? Or do we still just call this a regression fix, even though the regression has been in the wild for 3 years & 10 releases...

Copy link
Contributor Author

@jswitzer jswitzer Apr 25, 2019

Choose a reason for hiding this comment

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

Yes it definitely is an interface change (or more-precisely, change back?) and I suppose there could be projects out there that modified the interface they expected and then will have to modify it again.

I think some kind of behavior change is called for though, whether or not we throw a different kind of (more catcheable than AttributeError) Exception or go back to the old behavior (defer exception until finish()). This PR would be for the latter option.

That being said, the project I'm working on could go either way - we'd be happy to just catch and ignore a specific-enough exception. I'd like to see some change made at the IRequest implementation level (not just wsgi level) - the project I'm working on is calling request.write() directly and that's what started to fail for disconnected clients when we upgraded from twisted 15 -> 18.

@arnimarj
Copy link

I reported a while ago, something which I believe is caused by the same underlying issue:

https://twistedmatrix.com/trac/ticket/9300

The wsgi framework had scheduled pending writes on the reactor thread, which were then executed after the channel was closed. The writes were scheduled before the channel was closed, so I concluded it was a bug in the wsgi code. An attempt at a fix, and (very tricky) tests are at:

#907

@exarkun
Copy link
Member

exarkun commented Apr 26, 2019

I reported a while ago, something which I believe is caused by the same underlying issue:

https://twistedmatrix.com/trac/ticket/9300

The wsgi framework had scheduled pending writes on the reactor thread, which were then executed after the channel was closed. The writes were scheduled before the channel was closed, so I concluded it was a bug in the wsgi code. An attempt at a fix, and (very tricky) tests are at:

#907

Thanks for pointing this out! It looks like you did a lot of work on testing in that PR - for a thing that's pretty difficult to test (multithreaded race conditions, actually I think someone proved those impossible to test).

The difficulty of testing a fix in the WSGI implementation suggests fixing it in IRequest may be the way to go. So far, no one has replied at all to the thread I started on the mailing list (but it hasn't been very long yet). If we go about a week with no response then I'll forget the concerns about backward compatibility.

@arnimarj
Copy link

difficulty of testing a fix in the WSGI implementation suggests fixing it in IRequest may be the way to go. So far, no one has replied at all to the thread I started on the mailing list (but it hasn't been very long yet). If we go about a week with no response then I'll forget the concerns about backward compatibility.

Indeed, the tests were notoriously difficult to design, and yet the fixes looks innocent enough.

The pragmatism of the proposed solution is very appealing since the error-condition is eventually signaled via Request.finish().

@exarkun
Copy link
Member

exarkun commented Apr 29, 2019

No luck starting a discussion on the topic (see https://twistedmatrix.com/pipermail/twisted-python/2019-April/032293.html). Using my executive power I'm going to approve the change in behavior. I'll try to re-review for the other minor issues I raised in my first review (I can probably find time for that between today and May 2 - after that I'm totally unavailable for at least 2 weeks) - just re-add the review keyword in trac when you think it's ready for another look.

Thanks again for your efforts so far.

Copy link
Member

@exarkun exarkun left a comment

Choose a reason for hiding this comment

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

Thanks! A couple more very minor comments inline then I think this is mergeable. The actual behavior and tests look just right.

src/twisted/newsfragments/9410.bugfix Outdated Show resolved Hide resolved
src/twisted/web/http.py Outdated Show resolved Hide resolved
@exarkun exarkun merged commit c8d59d6 into twisted:trunk May 17, 2019
@cjw296
Copy link

cjw296 commented Jun 25, 2019

@exarkun - has this made it into a release yet? Sorry if I've missed a better way to track; if there is a way I could have figured this out for myself, what would it be?

@exarkun
Copy link
Member

exarkun commented Jun 26, 2019

@exarkun - has this made it into a release yet? Sorry if I've missed a better way to track; if there is a way I could have figured this out for myself, what would it be?

I think not. Latest Twisted is 19.2.1 - that's a release from Feb 2019 (2019-02) w/ a security fix. This wasn't merged until May (2019-05). So that's one way to figure it out. Another way is to look at NEWS.rst and search for the ticket number. It will only be there once it has been included in a release (and it'll be under a heading for the release it first appeared in).

@glyph
Copy link
Member

glyph commented Aug 3, 2019

It will be in 19.7.0 which is in pre-release, has a reviewed ticket, and should be out any day now.

@cjw296
Copy link

cjw296 commented Aug 30, 2019

Okay, so now in similar circumstances, we get:


2019-08-30 07:01:45.270 | 2019-08-30T01:01:45-0500 [twisted.internet.defer#critical] Unhandled error in Deferred:
-- | --
2019-08-30 07:01:45.270 | 2019-08-30T01:01:45-0500 [twisted.internet.defer#critical]
2019-08-30 07:01:45.270 | Traceback (most recent call last):
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/internet/defer.py", line 460, in callback
2019-08-30 07:01:45.270 | self._startRunCallbacks(result)
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2019-08-30 07:01:45.270 | self._runCallbacks()
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-08-30 07:01:45.270 | current.result = callback(current.result, *args, **kw)
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2019-08-30 07:01:45.270 | _inlineCallbacks(r, g, status)
2019-08-30 07:01:45.270 | --- <exception caught here> ---
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2019-08-30 07:01:45.270 | result = g.send(result)
2019-08-30 07:01:45.270 | request.finish()
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/web/server.py", line 268, in finish
2019-08-30 07:01:45.270 | return http.Request.finish(self)
2019-08-30 07:01:45.270 | File "/usr/lib64/python3.6/site-packages/twisted/web/http.py", line 1071, in finish
2019-08-30 07:01:45.270 | "Request.finish called on a request after its connection was lost; "
2019-08-30 07:01:45.270 | builtins.RuntimeError: Request.finish called on a request after its connection was lost; use Request.notifyFinish to keep track of this.

Is this a new/different bug? If so, where's it being tracked?

@jswitzer
Copy link
Contributor Author

jswitzer commented Sep 3, 2019

@cjw296 Please create a new trac issue for this: https://twistedmatrix.com/trac/newticket

You will need to log into trac with your github account first.

It's not obvious that this is or isn't a bug. In the ticket, please provide some more context into how you're using twisted and how the behaviour may have changed.

You can reference https://twistedmatrix.com/trac/ticket/9410 if you think it's related.

@glyph
Copy link
Member

glyph commented Nov 2, 2019

@cjw296 Did you ever file that bug?

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

6 participants