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

[willgraf]

Below is a minimal example. Large file uploads are failing on TLS servers while smaller file uploads work as expected. This could be a duplicate of #185, but I'm seeing a different stack trace. (Originally from vanvalenlab/kiosk-client#59)

import logging, os, sys, tempfile

import numpy as np
import tifffile

import treq
from twisted.internet import reactor, defer

def save_image(path, size):
    x = np.random.random(size).astype('float32')
    tifffile.imsave(path, x)

@defer.inlineCallbacks
def upload_file(host, filepath):
    with open(filepath, 'rb') as f:
        request = treq.post(host, files={'file': (filepath, f)})
        response = yield request
        json_content = yield response.json()
        print(json_content)

if __name__ == '__main__':
    logger = logging.getLogger()
    console = logging.StreamHandler(stream=sys.stdout)
    console.setLevel(logging.DEBUG)
    logger.addHandler(console)

    with tempfile.TemporaryDirectory() as temp_dir:
        path = os.path.join(temp_dir, 'bigTestImage.tiff')
        # save_image(path, (2, 100, 100))  # this one works
        save_image(path, (2, 10000, 10000))  # this one fails
        upload_file('https://httpbin.org/post', path)

    reactor.run()

---

The stack trace:

Unhandled Error
Traceback (most recent call last):
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/selectreactor.py", line 149, in _doReadOrWrite
    why = getattr(selectable, method)()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/tcp.py", line 243, in doRead
    return self._dataReceived(data)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/tcp.py", line 249, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/endpoints.py", line 132, in dataReceived
    return self._wrappedProtocol.dataReceived(data)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/protocols/tls.py", line 325, in dataReceived
    self._unbufferPendingWrites()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/protocols/tls.py", line 498, in _unbufferPendingWrites
    self._producer.resumeProducing()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/protocols/tls.py", line 101, in resumeProducing
    self._producer.resumeProducing()
  File "/Users/willgraf/env/lib/python3.7/site-packages/treq/multipart.py", line 117, in resumeProducing
    self._currentProducer.resumeProducing()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/web/client.py", line 1217, in resumeProducing
    self._task.resume()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/task.py", line 460, in resume
    raise NotPaused()
twisted.internet.task.NotPaused: 

Unexpected exception from treq.multipart.MultiPartProducer.stopProducing
Traceback (most recent call last):
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/protocols/policies.py", line 125, in connectionLost
    self.wrappedProtocol.connectionLost(reason)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1050, in dispatcher
    return func(*args, **kwargs)
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1734, in _connectionLost_TRANSMITTING
    self._currentRequest.stopWriting()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/web/_newclient.py", line 951, in stopWriting
    _callAppFunction(self.bodyProducer.stopProducing)
--- <exception caught here> ---
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/web/_newclient.py", line 197, in _callAppFunction
    function()
  File "/Users/willgraf/env/lib/python3.7/site-packages/treq/multipart.py", line 91, in stopProducing
    self._currentProducer.stopProducing()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/web/client.py", line 1161, in stopProducing
    self._task.stop()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/task.py", line 497, in stop
    self._checkFinish()
  File "/Users/willgraf/env/lib/python3.7/site-packages/twisted/internet/task.py", line 507, in _checkFinish
    raise self._completionState
twisted.internet.task.TaskStopped: 

---

My environment:

$ pip freeze

attrs==20.3.0
Automat==20.2.0
certifi==2020.12.5
cffi==1.14.4
chardet==4.0.0
constantly==15.1.0
cryptography==3.3.1
hyperlink==21.0.0
idna==3.1
incremental==17.5.0
numpy==1.19.5
pyasn1==0.4.8
pyasn1-modules==0.2.8
pycparser==2.20
PyHamcrest==2.0.2
pyOpenSSL==20.0.1
requests==2.25.1
service-identity==18.1.0
six==1.15.0
tifffile==2021.1.14
treq==21.1.0
Twisted==20.3.0
urllib3==1.26.3
zope.interface==5.2.0

[twm]

Thanks for the report!

I spent a bit of time poking at this tonight. I'm not too familiar with this part of treq, but I am pretty sure that there is a reentrancy issue in MultipartProducer. There are a number of places where it does multiple writes to the consumer without checking if it has been paused. I've no doubt that this is a bug in treq, but I'll need to spend some more time on this before I'm confident in my diagnosis or how to fix it.

To be clear, I'm not sure when I'll get back to this. If you need a fix for this urgently I suggest that you take a crack at it yourself.