AttributeError: 'str' object has no attribute 'items'

[symphorien]

2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO Failed to handle edu 'm.receipt'
2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO Traceback (most recent call last):                              
2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO   File "/nix/store/08q3wjbab0kqaa3qr0nhamdhzkjcy6pb-matrix-synapse-1.37.1/lib/python3.8/site-packages/synapse/federation/federation_server.py", line 1118, in on_edu                                                                                                                                  
2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO     await handler(origin, content)                                                                 
2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO   File "/nix/store/08q3wjbab0kqaa3qr0nhamdhzkjcy6pb-matrix-synapse-1.37.1/lib/python3.8/site-packages/synapse/handlers/receipts.py", line 62, in _received_remote_receipt                                                                                                                             
2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO     for receipt_type, users in room_values.items():                                                     
2021-07-12T11:46:22.104 2587790268211 matrix-synapse.service homeserver[2934508] INFO AttributeError: 'str' object has no attribute 'items'                                              

Synapse 1.37.1, nixos 21.05, linux x86_64

[anoadragon453]

This looks to have been caused by receiving a malformed m.receipt event over federation. A valid m.receipt should look like:

{
  "content": {
    "!some_room:example.org": {
      "m.read": {
        "@john:matrix.org": {
          "data": {
            "ts": 1533358089009
          },
          "event_ids": [
            "$read_this_event:matrix.org"
          ]
        }
      }
    }
  },
  "edu_type": "m.presence"
}

but the one you received seems to have a something like:

{
  "content": {
    "!some_room:example.org": "some string" // this should be a dict, not a string
  },
  "edu_type": "m.presence"
}

Interestingly, I just noticed that the official example of an m.receipt in the currently unstable spec includes:

{
  "content": {
    ...
    "key": "value"
  },
  ...
}

That "key": "value" bit is invalid and most definitely a typo. I wonder if someone copied that example and tried it out in the real world...

In any case, Synapse should guard against this and check the type of each field (or simply catch the relevant Exception) instead of presumably returning a 500 to the remote server see #10376 (comment).

[ShadowJonathan]

This is both a validation bug in synapse, and a serialisation bug on another server, do you have any idea which server this EDU came from?

[anoadragon453]

Note that Synapse should simply fail this particular EDU and move on with the rest of the transaction (so it likely won't return a 500 to the remote server).

We catch broad Exceptions while handling each EDU here:

synapse/synapse/federation/federation_server.py

Lines 1113 to 1123 in c54db67

	# Check if we have a handler on this instance
	handler = self.edu_handlers.get(edu_type)
	if handler:
	with start_active_span_from_edu(content, "handle_edu"):
	try:
	await handler(origin, content)
	except SynapseError as e:
	logger.info("Failed to handle edu %r: %r", edu_type, e)
	except Exception:
	logger.exception("Failed to handle edu %r", edu_type)
	return

[symphorien]

This is both a validation bug in synapse, and a serialisation bug on another server, do you have any idea which server this EDU came from?

I suspect it's tedomum.net but I have no proof. If you provide me with a patch adding some more logging at >= Warning level (I'm filtering the logs) I can run this for a few days (it happens several times per day).

[src-r-r]

When is this (referring to #10376 (comment)) reproduced? What events take place and what's the setup?

[symphorien]

It has not happened to me in the last two weeks. I don't know steps to reproduce.

[squahtx]

matrix.org's Sentry instance has captured a few of these from July 2021. It doesn't seem to be happening anymore.

https://sentry.matrix.org/sentry/synapse-matrixorg/issues/118010
https://sentry.matrix.org/sentry/synapse-matrixorg/issues/224761

The originating server was platypus-sandbox.com and room_values was "{}" (an empty dict, as a string).

[lukasdenk]

@symphorien, @squahtx: Is this issue still relevant then? Or should it be closed?