Error while producing a thumbnail: 'NoneType' object has no attribute 'unregisterProducer'

[anoadragon453]

Description

Exception while producing a thumbnail for a valid file.

2019-05-31 11:55:56,270 - synapse.access.http.8008 - 233 - INFO - GET-1116745- 176.14.254.64 - 8008 - Received request: GET /_matrix/media/v1/thumbnail/amorgan.xyz/JpHpuDNOxuALIaPSENEAzZIu?width=800&height=600
2019-05-31 11:55:56,273 - synapse.access.http.8008 - 302 - INFO - GET-1116745- 176.14.254.64 - 8008 - {None} Processed request: 0.003sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.001sec/2) 92715B 200 "GET /_matrix/media/v1/thumbnail/amorgan.xyz/JpHpuDNOxuALIaPSENEAzZIu?width=800&height=600 HTTP/1.0" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:67.0) Gecko/20100101 Firefox/67.0" [0 dbevts]
2019-05-31 11:55:56,321 - synapse.access.http.8008 - 233 - INFO - GET-1116746- 176.14.254.64 - 8008 - Received request: GET /_matrix/media/v1/thumbnail/amorgan.xyz/chzgDJfCkiDOFITyulcRWQOn?width=40&height=40&method=crop
2019-05-31 11:55:56,322 - synapse.http.site - 203 - WARNING - GET-1116746- Error processing request <XForwardedForRequest at 0x7feb7a25e860 method='GET' uri='/_matrix/media/v1/thumbnail/amorgan.xyz/chzgDJfCkiDOFITyulcRWQOn?width=40&height=40&method=crop' clientproto='HTTP/1.0' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly.
2019-05-31 11:55:56,325 - synapse.rest.media.v1._base - 192 - WARNING - GET-1116746- Failed to write to consumer: <class 'AttributeError'> 'NoneType' object has no attribute 'registerProducer'
2019-05-31 11:55:56,325 - synapse.http.server - 112 - ERROR - GET-1116746- Failed handle request via 'ThumbnailResource': <XForwardedForRequest at 0x7feb7a25e860 method='GET' uri='/_matrix/media/v1/thumbnail/amorgan.xyz/chzgDJfCkiDOFITyulcRWQOn?width=40&height=40&method=crop' clientproto='HTTP/1.0' site=8008>
Traceback (most recent call last):
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/storage/_base.py", line 527, in runWithConnection
    defer.returnValue(result)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: [{'thumbnail_width': 32, 'thumbnail_type': 'image/png', 'thumbnail_height': 32, 'thumbnail_length': 2341, 'thumbnail_method': 'crop'}, {'thumbnail_width': 239, 'thumbnail_type': 'image/png', 'thumbnail_height': 240, 'thumbnail_length': 84450, 'thumbnail_method': 'scale'}, {'thumbnail_width': 399, 'thumbnail_type': 'image/png', 'thumbnail_height': 400, 'thumbnail_length': 196365, 'thumbnail_method': 'scale'}, {'thumbnail_width': 96, 'thumbnail_type': 'image/png', 'thumbnail_height': 96, 'thumbnail_length': 16151, 'thumbnail_method': 'crop'}]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/storage/_base.py", line 487, in runInteraction
    defer.returnValue(result)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: [{'thumbnail_width': 32, 'thumbnail_type': 'image/png', 'thumbnail_height': 32, 'thumbnail_length': 2341, 'thumbnail_method': 'crop'}, {'thumbnail_width': 239, 'thumbnail_type': 'image/png', 'thumbnail_height': 240, 'thumbnail_length': 84450, 'thumbnail_method': 'scale'}, {'thumbnail_width': 399, 'thumbnail_type': 'image/png', 'thumbnail_height': 400, 'thumbnail_length': 196365, 'thumbnail_method': 'scale'}, {'thumbnail_width': 96, 'thumbnail_type': 'image/png', 'thumbnail_height': 96, 'thumbnail_length': 16151, 'thumbnail_method': 'crop'}]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/rest/media/v1/_base.py", line 187, in respond_with_responder
    yield responder.write_to_consumer(request)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/rest/media/v1/media_storage.py", line 263, in write_to_consumer
    FileSender().beginFileTransfer(self.open_file, consumer)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/protocols/basic.py", line 923, in beginFileTransfer
    self.consumer.registerProducer(self, False)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/web/http.py", line 961, in registerProducer
    self.channel.registerProducer(producer, streaming)
AttributeError: 'NoneType' object has no attribute 'registerProducer'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/rest/media/v1/thumbnail_resource.py", line 71, in _async_render_GET
    request, media_id, width, height, method, m_type
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/rest/media/v1/thumbnail_resource.py", line 121, in _respond_local_thumbnail
    yield respond_with_responder(request, responder, t_type, t_length)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/synapse/rest/media/v1/_base.py", line 196, in respond_with_responder
    request.unregisterProducer()
  File "/home/ops/.synapse3/env3/lib/python3.5/site-packages/twisted/web/http.py", line 967, in unregisterProducer
    self.channel.unregisterProducer()
AttributeError: 'NoneType' object has no attribute 'unregisterProducer'
2019-05-31 11:55:56,326 - synapse.http.server - 415 - WARNING - GET-1116746- Not sending response to request <XForwardedForRequest at 0x7feb7a25e860 method='GET' uri='/_matrix/media/v1/thumbnail/amorgan.xyz/chzgDJfCkiDOFITyulcRWQOn?width=40&height=40&method=crop' clientproto='HTTP/1.0' site=8008>, already disconnected.
2019-05-31 11:55:56,326 - synapse.access.http.8008 - 302 - INFO - GET-1116746- 176.14.254.64 - 8008 - {None} Processed request: 0.005sec/-0.004sec (0.000sec, 0.000sec) (0.001sec/0.002sec/2) 0B 200! "GET /_matrix/media/v1/thumbnail/amorgan.xyz/chzgDJfCkiDOFITyulcRWQOn?width=40&height=40&method=crop HTTP/1.0" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:67.0) Gecko/20100101 Firefox/67.0" [0 dbevts]

Version information

• Homeserver: amorgan.xyz

• Version: 0.99.5.1 release build

• Install method: pip

• Platform: Debian, no containers

[richvdh]

I wonder if #4594 is related here.

[lugino-emeritus]

On my server synapse 1.3.1 shows the same error sometimes (ubuntu, virtualenv).

[zwieberl]

I'm getting the same on Raspian with v1.3.1

[richvdh]

The fact that this also happens for /key/v2/query (see #6700) suggests that this is not specific to media.

What has happened here is that the client has timed out (causing request.channel to be set to None) before we have finished processing the request; then, when we create a Producer and tell it to start producing (either in respond_with_json_bytes or in Responder.write_to_consumer in the media store), it has nowhere to produce to.

For most rest endpoints, we've worked around this by checking request._disconnected in respond_with_json (https://github.com/matrix-org/synapse/blob/release-v1.8.0/synapse/http/server.py#L456), so an easy solution here is to copy that check into the other places that send a response.

(alternative solutions might include being better at cancelling whatever we're doing when the client disconnects (#3528).)

[richvdh]

oh, and just to reiterate: the error is harmless, except for the noise in the log (and the fact that its presence means that the client timed out before it got a response).

[progserega]

such harmless error for for download file:

    2020-06-30 18:17:39,797 - synapse.http.site - 218 - WARNING - GET-1039934 - Error processing request <SynapseRequest at 0x7fe324433668 method='GET' uri='/_matrix/media/v1/download/rsprim.ru/xrlhoBpYaDjiUFGOFQEElOJK' clientproto='HTTP/1.0' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was     __closed cleanly.
    2020-06-30 18:17:39,799 - synapse.rest.media.v1._base - 227 - WARNING - GET-1039934 - Failed to write to consumer: <class 'AttributeError'> 'NoneType' object has no attribute 'registerProducer'
    2020-06-30 18:17:39,800 - synapse.http.server - 113 - ERROR - GET-1039934 - Failed handle request via 'DownloadResource': <SynapseRequest at 0x7fe324433668 method='GET' uri='/_matrix/media/v1/download/rsprim.ru/xrlhoBpYaDjiUFGOFQEElOJK' clientproto='HTTP/1.0' site=8008>
    Traceback (most recent call last): 
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
        result = g.send(result)
    StopIteration: {'media_type': 'image/jpeg', 'media_length': 19028, 'url_cache': None, 'upload_name': 'IMG_20200630_175019.jpg', 'created_ts': 1593503454719, 'quarantined_by': None}
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last): 
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
        result = g.send(result)
    StopIteration: {'media_type': 'image/jpeg', 'media_length': 19028, 'url_cache': None, 'upload_name': 'IMG_20200630_175019.jpg', 'created_ts': 1593503454719, 'quarantined_by': None}
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last): 
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/http/server.py", line 81, in wrapped_request_handler
        await h(self, request)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/rest/media/v1/download_resource.py", line 58, in _async_render_GET
        await self.media_repo.get_local_media(request, media_id, name)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/rest/media/v1/media_repository.py", line 205, in get_local_media
        request, responder, media_type, media_length, upload_name
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
        result = g.send(result)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/rest/media/v1/_base.py", line 231, in respond_with_responder
        request.unregisterProducer()
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/web/http.py", line 993, in unregisterProducer
        self.channel.unregisterProducer()
    AttributeError: 'NoneType' object has no attribute 'unregisterProducer'

version of synapse: 1.15.1 (debian 9.12)