Federation dying with AttributeError: 'dict' object has no attribute 'edu_type' or ... no attribute 'content'

[dkasak]

Description

After upgrading my homeserver to 1.51.0 yesterday, I noticed people on other homeservers weren't responding to my messages. On the receiving side some messages were getting through to me, but not all of them.

Digging into the logs, I noticed my Synapse wasn't able to process some transactions, failing with errors like:

2022-02-02 13:01:41,267 - synapse.federation.transport.server.federation:91 | INFO - PUT-82644 - Received txn 1643718649381 from matrix.org. (PDUs: 50, EDUs: 98)
2022-02-02 13:01:41,267 - synapse.federation.transport.server.federation:114 | ERROR - PUT-82644 - 'dict' object has no attribute 'edu_type'
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: {'ed25519:a_RXGa': FetchKeyResult(verify_key=<nacl.signing.VerifyKey object at 0x814e38370>, valid_until_ts=1643844371003)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/synapse/federation/transport/server/federation.py", line 101, in on_PUT
    device_list_updates = [
  File "/usr/local/lib/python3.8/site-packages/synapse/federation/transport/server/federation.py", line 104, in <listcomp>
    if edu.edu_type in DEVICE_UPDATE_EDUS
AttributeError: 'dict' object has no attribute 'edu_type'

The offending line seems to have been introduced in #11760. I'm not sure why that logger was automatically enabled for me (should it have been?), but as a workaround I reduced DEBUG to WARN and things started working again.

Version information

• Homeserver: termina.org.uk
• Version: 1.51.0
• Install method: package manager
• Platform: FreeBSD 12

[DMRobertson]

I'm not sure why that logger was automatically enabled for me (should it have been?)

I don't think so: unless you had debug logging configured everywhere?

I think the problem is that I copied and pasted logging from the sender side to the receiver side. But the receiver side just has a JsonDict; not a fully-fledged container of Edu structs. Frustrating that mypy didn't spot this, but I guess that's our fault for using Dict[str, Any] (not to mention my fault for not testing).

[DMRobertson]

It seems that none of our unit tests in tests/federation hit this code path. Presumably sytest and complement would do. That's all somewhat moot though, given that this would only show up if SYNAPSE_TEST_LOG_LEVEL=DEBUG or similar.

[dkasak]

I don't think so: unless you had debug logging configured everywhere?

Ah right, I had

loggers:
    synapse:
        level: DEBUG

    synapse.storage.SQL:
        level: ERROR

So that also trickles down to all loggers lower in the hierarchy. All good then.

[DMRobertson]

Reopening this: Fix was incorrect and the problem still occurs, just with a different error message.