Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#8558 defect closed fixed (fixed)

Window increments after stream closure cause MissingStreamError.

Reported by: Cory Benfield Owned by: Cory Benfield
Priority: high Milestone: Twisted 16.3.1
Component: web Keywords:
Cc: Branch: 8558-lukasa-missingstreamerror
branch-diff, diff-cov, branch-cov, buildbot
Author:

Description

Reported originally on the Twisted mailing list: https://twistedmatrix.com/pipermail/twisted-python/2016-July/030514.html

This occurs in any situation where the Resource finishes serving but there is data in the receive buffer that may include, amongst other things, a WindowUpdate for the stream that is now complete. hyper-h2 tolerates this just fine, but Twisted's code mistakenly expects that stream to be present still in the priority tree and in its own stream metadata, which it will not be. Causes the following traceback:

	Traceback (most recent call last):
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/python/log.py", line 101, in callWithLogger
	    return callWithContext({"system": lp}, func, *args, **kw)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/python/log.py", line 84, in callWithContext
	    return context.call({ILogContext: newCtx}, func, *args, **kw)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/python/context.py", line 118, in callWithContext
	    return self.currentContext().callWithContext(ctx, func, *args, **kw)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/python/context.py", line 81, in callWithContext
	    return func(*args,**kw)
	--- <exception caught here> ---
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/internet/selectreactor.py", line 149, in _doReadOrWrite
	    why = getattr(selectable, method)()
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/internet/tcp.py", line 209, in doRead
	    return self._dataReceived(data)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/internet/tcp.py", line 215, in _dataReceived
	    rval = self.protocol.dataReceived(data)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/protocols/tls.py", line 430, in dataReceived
	    self._flushReceiveBIO()
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/protocols/tls.py", line 400, in _flushReceiveBIO
	    ProtocolWrapper.dataReceived(self, bytes)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/protocols/policies.py", line 120, in dataReceived
	    self.wrappedProtocol.dataReceived(data)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/web/http.py", line 2334, in dataReceived
	    return self._channel.dataReceived(data)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/web/_http2.py", line 166, in dataReceived
	    self._handleWindowUpdate(event)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/twisted/web/_http2.py", line 583, in _handleWindowUpdate
	    self.priority.unblock(streamID)
	  File "/Users/cory/tmp/testh2/env/lib/python3.5/site-packages/priority/priority.py", line 359, in unblock
	    raise MissingStreamError("Stream %d not in tree" % stream_id)
	priority.priority.MissingStreamError: 'Stream 1 not in tree'

Change History (10)

comment:1 Changed 4 years ago by Cory Benfield <lukasaoz@…>

In faf0175:

Add test for #8558.

comment:2 Changed 4 years ago by Cory Benfield

Branch: 8558-lukasa-missingstreamerror

Ok, an initial branch has been pushed. See https://github.com/twisted/twisted/pull/290

comment:3 Changed 4 years ago by Cory Benfield

Keywords: review added

comment:4 Changed 4 years ago by Adi Roiban

Keywords: review removed
Owner: set to Cory Benfield

Changes look good. Please see my inline comment for the PR.

Now, going for the 5 whys. Why is curl sending an update after the stream was done?

Is this a bug in curl?

Please clarify the code and then merge. Thanks!

comment:5 Changed 4 years ago by Cory Benfield

It's not a bug in curl, it's the nature of protocols that communicate simultaneously in both directions. Essentially, this sequence of events was happening:

  • Twisted sent a DATA frame containing some data, which shrinks the flow control window.
  • curl received the DATA frame and decided to open the flow control window for the stream by sending a WINDOW_UPDATE frame.
  • Meanwhile, Twisted realised that the body data was complete, and closed the stream by sending END_STREAM.
  • The WINDOW_UPDATE frame and the END_STREAM were both on the network at the same time.
  • From Twisted's perspective, the stream was done and it could remove its state.
  • Then Twisted received the WINDOW_UPDATE, for a stream that from its perspective is still over.

This isn't a bug: while curl could in principle have avoided sending the WINDOW_UPDATE, there is nothing wrong with it doing so. This is why hyper-h2 allowed it to happen, and why Twisted should too.

I'll clear up the code per your feedback.

comment:6 Changed 4 years ago by Adi Roiban

Thanks for the explanation.

From my point of view, if possible the review reply itself should contain as little text as possible as the code should contain as much information as possible.

Later if someone will try to hunt a different bug, they might bump into the current code and might question the reason why we have the current code.

I think that a brief comment describing the condition which is handled there... we should not be to verbose with code comments to minimize the risk for having the comment get out of sync with the implementation.


Your comment talks about the current well-behaved curl client, but I think that the current code is also handles buggy implementation which are sending windows updates for a stream which was never really created :)... now I know that it might be hard to tell if that streamID was ever created before

comment:7 Changed 4 years ago by hawkowl

Milestone: Twisted 16.3.1

comment:8 Changed 4 years ago by Cory Benfield

Hawkie has given me permission to ignore the current static files failure, which is apparently the result of #8563. So I'm going ahead with adi's original feedback to merge.

comment:9 Changed 4 years ago by GitHub <noreply@…>

Resolution: fixed
Status: newclosed

In b348b59:

Merge pull request #290 from twisted/8558-lukasa-missingstreamerror: Resolve MissingStreamError on WINDOW_UPDATE

Author: Lukasa
Reviewer: adiroiban
Fixes: #8558

comment:10 Changed 4 years ago by Amber Brown (HawkOwl) <hawkowl@…>

In eb157b8:

Merge pull request #290 from twisted/8558-lukasa-missingstreamerror: Resolve MissingStreamError on WINDOW_UPDATE

Author: Lukasa
Reviewer: adiroiban
Fixes: #8558

Note: See TracTickets for help on using tickets.