Synapse: Event with `m.relates_to: null` causes 500 error (AttributeError: 'NoneType' object has no attribute 'get')

Created on 9 Jun 2019  Â·  12Comments  Â·  Source: matrix-org/synapse

Description


After update to homeserver.py version 0.99.5.2 - in logs I get errors:

      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/util/metrics.py", line 63, in measured_func
        r = yield func(self, *args, **kwargs)
      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/handlers/message.py", line 608, in create_new_client_event
        if relation.get("rel_type") == RelationTypes.ANNOTATION:
    AttributeError: 'NoneType' object has no attribute 'get'

error.log

Version information

deb packet: matrix-synapse-py3 0.99.5.2+stretch1 amd64
Debian 9.8
LXC container.

bug p2
Source
picture progserega
👍1

Most helpful comment

It's clear that returning a 500 and logging a stacktrace is not the correct behaviour. As per the matrix-doc issue, there is scope to debate whether the correct behaviour is to treat the event as invalid and return a 400, or to ignore the invalid m.relates_to.

picture richvdh on 15 Jul 2019
👍2

All 12 comments

Seeing this on 1.0.0 as well. Possibly introduced in #5212?

silkeh picture silkeh on 12 Jun 2019

I see this happens when you try to send an event. What is the body of the event you are sending?

richvdh picture richvdh on 27 Jun 2019

I do not know.
On new server I got (may be this is other error...):

    2019-06-30 08:02:18,475 - synapse.access.http.8008 - 233 - INFO - GET-2520523- ::1 - 8008 - Received request: GET /_matrix/media/v1/thumbnail/rsprim.ru/bDSYwzHrPnqHMQXWHXgfzIgf?width=40&height=40&method=crop
    2019-06-30 08:02:18,480 - synapse.http.site - 203 - WARNING - GET-2520523- Error processing request <SynapseRequest at 0x7fb76d5e1160 method='GET' uri='/_matrix/media/v1/thumbnail/rsprim.ru/bDSYwzHrPnqHMQXWHXgfzIgf?width=40&height=40&method=crop' clientproto='HTTP/1.0' site=8008>: <class 'twisted.internet.error.C    __onnectionDone'> Connection was closed cleanly.
    2019-06-30 08:02:18,481 - synapse.access.http.8008 - 233 - INFO - GET-2520524- 127.0.0.1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s832087_40098896_16971_1423230_276637_1059_25628_174542_407
    2019-06-30 08:02:18,482 - synapse.util.caches.response_cache - 151 - INFO - GET-2520524- [sync]: no cached result for [(@svc_disp_340-00:rsprim.ru, 30000, 's832087_40098896_16971_1423230_276637_1059_25628_174542_407', '3', False, 'YKYJJDGEYD')], calculating new one
    2019-06-30 08:02:18,485 - synapse.rest.media.v1._base - 192 - WARNING - GET-2520523- Failed to write to consumer: <class 'AttributeError'> 'NoneType' object has no attribute 'registerProducer'
    2019-06-30 08:02:18,486 - synapse.http.server - 112 - ERROR - GET-2520523- Failed handle request via 'ThumbnailResource': <SynapseRequest at 0x7fb76d5e1160 method='GET' uri='/_matrix/media/v1/thumbnail/rsprim.ru/bDSYwzHrPnqHMXXWHQgfzIgf?width=40&height=40&method=crop' 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)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py", line 527, in runWithConnection
        defer.returnValue(result)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
        raise _DefGen_Return(val)
    twisted.internet.defer._DefGen_Return: [{'thumbnail_width': 320, 'thumbnail_length': 5353, 'thumbnail_height': 51, 'thumbnail_method': 'scale', 'thumbnail_type': 'image/jpeg'}, {'thumbnail_width': 96, 'thumbnail_length': 4181, 'thumbnail_height': 96, 'thumbnail_method': 'crop', 'thumbnail_type': 'image/jpeg'}, {'    __thumbnail_width': 800, 'thumbnail_length': 19420, 'thumbnail_height': 129, 'thumbnail_method': 'scale', 'thumbnail_type': 'image/jpeg'}, {'thumbnail_width': 32, 'thumbnail_length': 1122, 'thumbnail_height': 32, 'thumbnail_method': 'crop', 'thumbnail_type': 'image/jpeg'}, {'thumbnail_width': 640, 'thumbnail_leng    __th': 14015, 'thumbnail_height': 103, 'thumbnail_method': 'scale', 'thumbnail_type': 'image/jpeg'}]

    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)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/storage/_base.py", line 487, in runInteraction
        defer.returnValue(result)
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/internet/defer.py", line 1362, in returnValue
        raise _DefGen_Return(val)
    twisted.internet.defer._DefGen_Return: [{'thumbnail_width': 320, 'thumbnail_length': 5353, 'thumbnail_height': 51, 'thumbnail_method': 'scale', 'thumbnail_type': 'image/jpeg'}, {'thumbnail_width': 96, 'thumbnail_length': 4181, 'thumbnail_height': 96, 'thumbnail_method': 'crop', 'thumbnail_type': 'image/jpeg'}, {'    __thumbnail_width': 800, 'thumbnail_length': 19420, 'thumbnail_height': 129, 'thumbnail_method': 'scale', 'thumbnail_type': 'image/jpeg'}, {'thumbnail_width': 32, 'thumbnail_length': 1122, 'thumbnail_height': 32, 'thumbnail_method': 'crop', 'thumbnail_type': 'image/jpeg'}, {'thumbnail_width': 640, 'thumbnail_leng    __th': 14015, 'thumbnail_height': 103, 'thumbnail_method': 'scale', 'thumbnail_type': 'image/jpeg'}]

    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/rest/media/v1/_base.py", line 187, in respond_with_responder
        yield responder.write_to_consumer(request)
      File "/opt/venvs/matrix-synapse/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 "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/protocols/basic.py", line 923, in beginFileTransfer
        self.consumer.registerProducer(self, False) 
      File "/opt/venvs/matrix-synapse/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 "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/synapse/http/server.py", line 81, in wrapped_request_handler
        yield h(self, request)
      File "/opt/venvs/matrix-synapse/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 "/opt/venvs/matrix-synapse/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 "/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 196, in respond_with_responder
        request.unregisterProducer()
      File "/opt/venvs/matrix-synapse/lib/python3.5/site-packages/twisted/web/http.py", line 967, in unregisterProducer
        self.channel.unregisterProducer()
    AttributeError: 'NoneType' object has no attribute 'unregisterProducer'
    2019-06-30 08:02:18,501 - synapse.http.server - 415 - WARNING - GET-2520523- Not sending response to request <SynapseRequest at 0x7fb76d5e1160 method='GET' uri='/_matrix/media/v1/thumbnail/rsprim.ru/bDSYwzHrPnqHMQXWHXgfzIgf?width=40&height=40&method=crop' clientproto='HTTP/1.0' site=8008>, already disconnected.
    2019-06-30 08:02:18,501 - synapse.access.http.8008 - 302 - INFO - GET-2520523- ::1 - 8008 - {None} Processed request: 0.026sec/-0.021sec (0.003sec, 0.001sec) (0.001sec/0.003sec/2) 0B 200! "GET /_matrix/media/v1/thumbnail/rsprim.ru/bDSYwzHrPnqHMXXWHQgfzIgf?width=40&height=40&method=crop HTTP/1.0" "Mozilla/5.0 (Win    __dows NT 10.0; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0" [0 dbevts]
    2019-06-30 08:02:18,502 - synapse.metrics - 372 - INFO - - Collecting gc 0
progserega picture progserega on 30 Jun 2019

I think last error occur when user try get big image (more then 4000x4000 pixels).

progserega picture progserega on 30 Jun 2019

On new server I got (may be this is other error...):

yes, it seems to be unrelated, and probably #5304.

richvdh picture richvdh on 30 Jun 2019

At least one third-party bridge sends such events, and it used to work. It was broken in some Synapse update, hence it's certainly a regression.

https://github.com/tulir/mautrix-telegram/issues/336 this bridge has already worked around this problem, though

WGH- picture WGH- on 15 Jul 2019

@WGH-: please can you share an example of an event that causes this problem?

richvdh picture richvdh on 15 Jul 2019

I think an example of such event is provided in the opening message of the linked issue. Here's copy-paste:

[2019-06-15 21:32:07,871] [[email protected]] PUT /room/%21mMWGhycXzeDvpkjCzk%3Aroom409.xyz/send/m.room.message/61560634327871 {"body": "Forever", "msgtype": "m.text", "m.relates_to": null, "external_url": "https://t.me/c /1050980458/48908"} as user @telegram_163061100:room409.xyz

On July 15, 2019 12:32:55 PM GMT+03:00, Richard van der Hoff notifications@github.com wrote:

@WGH-: please can you share an example of an event that causes this
problem?

WGH- picture WGH- on 15 Jul 2019

thanks

richvdh picture richvdh on 15 Jul 2019

It's unclear to me what the correct behaviour is here. I've raised https://github.com/matrix-org/matrix-doc/issues/2178 to track

richvdh picture richvdh on 15 Jul 2019

Disclaimer: I'm not a developer of said bridge, and I took "It's a bug in synapse" (mentioned in that ticket) for granted. Maybe it's something more complicated.

This is the commits that seem to be related to it:
https://github.com/tulir/mautrix-telegram/commit/1693b643a7e25589365f2baecf78e02d10d44559
https://github.com/tulir/mautrix-python/commit/f6064bca716b4ce82399bdaa52c4b13b18cb707a

WGH- picture WGH- on 15 Jul 2019

It's clear that returning a 500 and logging a stacktrace is not the correct behaviour. As per the matrix-doc issue, there is scope to debate whether the correct behaviour is to treat the event as invalid and return a 400, or to ignore the invalid m.relates_to.

richvdh picture richvdh on 15 Jul 2019
👍2
Was this page helpful?
0 / 5 - 0 ratings

Related issues

clokep picture clokep  Â·  4Comments
alexrashed picture alexrashed  Â·  4Comments
ukcb picture ukcb  Â·  4Comments
richvdh picture richvdh  Â·  3Comments
babolivier picture babolivier  Â·  3Comments