POST with TLS causes double-close on body producer #185

dmurvihill · 2017-04-07T21:26:13Z

This appears to be caused by the body producer's stopProducing method being called both by the TCP protocol and the TLS protocol:

$ pip show treq
Name: treq
Version: 16.12.0
Summary: A requests-like API built on top of twisted.web's Agent
Home-page: http://github.com/twisted/treq
Author: Amber Brown
Author-email: hawkowl@twistedmatrix.com
License: MIT/X
Location: /Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages
Requires: incremental, requests, pyOpenSSL, six, service-identity, Twisted

$ pip show twisted
Name: Twisted
Version: 16.6.0
Summary: An asynchronous networking framework written in Python
Home-page: http://twistedmatrix.com/
Author: Glyph Lefkowitz
Author-email: glyph@twistedmatrix.com
License: MIT
Location: /Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages
Requires: constantly, zope.interface, incremental

$ cat test_treq_tls.py 
import treq
from twisted.internet import reactor                                                                       
treq.post('https://requestb.in/19qt4ei1', data=b'testdata').addBoth(lambda _: reactor.stop())
reactor.run()

$ python test_treq_tls.py 
Unexpected exception from twisted.web.client.FileBodyProducer.stopProducing
Traceback (most recent call last):
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/internet/endpoints.py", line 130, in connectionLost
    return self._wrappedProtocol.connectionLost(reason)
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/web/_newclient.py", line 929, in dispatcher
    return func(*args, **kwargs)
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/web/_newclient.py", line 1599, in _connectionLost_TRANSMITTING
    self._currentRequest.stopWriting()
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/web/_newclient.py", line 830, in stopWriting
    _callAppFunction(self.bodyProducer.stopProducing)
--- <exception caught here> ---
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/web/_newclient.py", line 194, in _callAppFunction
    function()
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/web/client.py", line 1041, in stopProducing
    self._task.stop()
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/internet/task.py", line 497, in stop
    self._checkFinish()
  File "/Users/dmurvihill/.venv/txbrake/lib/python2.7/site-packages/twisted/internet/task.py", line 507, in _checkFinish
    raise self._completionState
twisted.internet.task.TaskStopped:

Occurs on other versions of Twisted and Treq as well.

Both calls appear to originate in this method of tcp.Connection:

    def connectionLost(self, reason):
        """See abstract.FileDescriptor.connectionLost().
        """
        # Make sure we're not called twice, which can happen e.g. if
        # abortConnection() is called from protocol's dataReceived and then
        # code immediately after throws an exception that reaches the
        # reactor. We can't rely on "disconnected" attribute for this check
        # since twisted.internet._oldtls does evil things to it:
        if not hasattr(self, "socket"):
            return
        abstract.FileDescriptor.connectionLost(self, reason)  # (DM) first close occurs here
        self._closeSocket(not reason.check(error.ConnectionAborted))
        protocol = self.protocol
        del self.protocol
        del self.socket
        del self.fileno
        protocol.connectionLost(reason)  # (DM) second close occurs here

The text was updated successfully, but these errors were encountered:

horkhe · 2017-09-25T11:44:52Z

Still happening in Twisted v17.9.0 and treq v17.8.0

glyph · 2017-10-17T18:10:36Z

Oops. Totally missed this one. Tagging a few random maintainers @hawkowl @hynek @wsanchez in the hopes that someone will run this down…

glyph · 2017-10-17T18:10:43Z

(Thanks @horkhe for the ping)

exvito · 2017-11-12T13:02:06Z

My 2c.,

Reproduced on Mac OS 10.9.5 (yes, really old...):

Fresh Python 3.6 virtualenv.
pip install treq: brought in treq 17.8.0, Twisted 17.9.0 and dependencies.

Worked around / fixed with:

export SSL_CERT_FILE=$(python -m certifi)
No longer fails.

exvito · 2017-11-18T11:27:17Z

Digged further into this. Here's my understanding:

The failure does indeed result from a second call to stopProducing when the certificate validation fails:
- The first call comes from twisted.protocols.tls._ProducerMembrane.stopProducing.
- The second one comes from twisted.web._newclient.Request.stopWriting.
In this case, treq is using a FileBodyProducer from a file-like BytesIO object wrapping the post data bytes; this producer is used to deliver the request's body payload.
FileBodyProducer generates the unhandled exception when stopProducing is called on it a second time. Motive:
- It uses a twisted.internet.task to cooperatively read bytes from the underlying file and write them to the consumer.
- When stopProducing is called on FileBodyProducer, it calls stop on its task which raises the TaskStopped exception when it is already completed in twisted.internet.task.CooperativeTask._checkFinish.

So this does seem like a Twisted related issue.

Within my current understanding, addressing this may come down to design decisions around code I'm not totally familiar with:

Should a TLS wrapped producer have its stopProducing method called twice?
Should calling stopProducing twice on FileBodyProducer fail?
Should calling stop on a completed CooperativeTask fail?

I have no more time to dedicate to this today. My next steps would be:

Check if there's a bug logged for this aleady in Twisted's bug tracker.
If not, bring this issue to the Twisted's mailing list.

PS: for some reason this only happens when certificate validation fails; I'm not seeing a single call to stopProducing when the request/response cycle is completed successfully. Shouldn't there be one?

exvito · 2017-11-18T11:40:39Z

Short update:

https://twistedmatrix.com/trac/ticket/8473 is a related Twisted issue.
Cory Benfield comments the possibility of failure that is being observed in this case.

jlitzingerdev · 2017-11-18T22:30:51Z

The following may also be related:

https://twistedmatrix.com/trac/ticket/7457
https://twistedmatrix.com/trac/ticket/6528

jlitzingerdev · 2017-11-18T22:39:55Z

If it helps, I can generate the same error without treq using:
https://gist.github.com/jlitzingerdev/2b010b15d4772a41601e400c17c5386e

exvito · 2017-11-19T13:23:59Z

@jlitzingerdev, thanks for the extra investigation.

For easier reading, I've shortened your gist by quite a lot and created https://gist.github.com/exvito/b8298f25196d41daf67414f702518f6b

I guess it is time to bring this topic to the Twisted mailing list.

exvito · 2017-11-20T08:23:33Z

For a complete cross-reference, here's the message I posted to the Twisted mailing list: https://twistedmatrix.com/pipermail/twisted-python/2017-November/031730.html

horkhe · 2019-11-15T12:22:22Z

It has been awhile since the last update. Is it on the roadmap?

glyph · 2019-11-19T16:42:38Z

@horkhe There is no roadmap; these are all volunteer-maintained projects with very limited resources. If you could write a PR that addresses the issue, it would probably get fixed faster ;). I’d very much like to see this traceback resolved too.

The current specification for IBodyProducer states that implementations need to be written to allow simultaneous calls to pauseProducing, resumeProducing, and stopProducing. FileBodyProducer currently only complies with that for pause and resumeProducing (where comply is interpreted here as not raising an error). Instead of allowing the TaskFinished exception to be raised on multiple calls to stopProducing, catch and drop the exception. The use of "pass" is not ideal, but this avoids an internal book-keeping variable to track the stop state and a branch for the normal flow. The use of "pass" to handle stopped also appears within the inner maybeStopped function of startProducing, so it isn't without precedent. This has been discussed in several forums: * twisted/treq#185 (comment) * https://twistedmatrix.com/pipermail/twisted-python/2017-November/031730.html Related ticket(s): 7457 Regression risk: Existing uses of FileBodyProducer that rely on multiple calls to stopProducing to raise an exception will break.

jlitzingerdev mentioned this issue Nov 18, 2017

9280 web remove legacy log twisted/twisted#919

Merged

jlitzingerdev mentioned this issue Nov 27, 2019

fix exception from multiple calls to FileBodyProducer.stop twisted/twisted#1204

Merged

5 tasks

willgraf mentioned this issue Jun 26, 2020

Files over a certain size fail to upload to TLS enabled servers. vanvalenlab/kiosk-client#59

Open

willgraf mentioned this issue Jan 27, 2021

Large file uploads to TLS server fail due to TaskStopped error in MultiPartProducer.stopProducing #323

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

POST with TLS causes double-close on body producer #185

POST with TLS causes double-close on body producer #185

dmurvihill commented Apr 7, 2017

horkhe commented Sep 25, 2017

glyph commented Oct 17, 2017

glyph commented Oct 17, 2017

exvito commented Nov 12, 2017

exvito commented Nov 18, 2017 •

edited

Loading

exvito commented Nov 18, 2017

jlitzingerdev commented Nov 18, 2017 •

edited

Loading

jlitzingerdev commented Nov 18, 2017 •

edited

Loading

exvito commented Nov 19, 2017

exvito commented Nov 20, 2017

horkhe commented Nov 15, 2019 •

edited

Loading

glyph commented Nov 19, 2019

POST with TLS causes double-close on body producer #185

POST with TLS causes double-close on body producer #185

Comments

dmurvihill commented Apr 7, 2017

horkhe commented Sep 25, 2017

glyph commented Oct 17, 2017

glyph commented Oct 17, 2017

exvito commented Nov 12, 2017

exvito commented Nov 18, 2017 • edited Loading

exvito commented Nov 18, 2017

jlitzingerdev commented Nov 18, 2017 • edited Loading

jlitzingerdev commented Nov 18, 2017 • edited Loading

exvito commented Nov 19, 2017

exvito commented Nov 20, 2017

horkhe commented Nov 15, 2019 • edited Loading

glyph commented Nov 19, 2019

exvito commented Nov 18, 2017 •

edited

Loading

jlitzingerdev commented Nov 18, 2017 •

edited

Loading

jlitzingerdev commented Nov 18, 2017 •

edited

Loading

horkhe commented Nov 15, 2019 •

edited

Loading