Bug 2052551 - regression Bug in 1.51+ : msg can be send, but not received externally
Summary: regression Bug in 1.51+ : msg can be send, but not received externally
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: matrix-synapse
Version: 34
Hardware: x86_64
OS: Linux
unspecified
urgent
Target Milestone: ---
Assignee: Dan Callaghan
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-02-09 14:40 UTC by customercare
Modified: 2022-02-18 01:37 UTC (History)
4 users (show)

Fixed In Version: matrix-synapse-1.52.0-2.fc34 matrix-synapse-1.52.0-2.fc35
Clone Of:
Environment:
Last Closed: 2022-02-18 01:13:20 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description customercare 2022-02-09 14:40:38 UTC
Description of problem:

Yesterday night, matrix-synapse updated to 1.51 . Since then, the Exceptions below apear in the log and messages from other server i.e. matrix.org can't be received. it's still possible to send message externally.

Interestingly, internal messages are not touched by this. 

WORKAROUND:

A downgrade to 1.49.2 fixed the issue instantly, so i think, it's a regression.

Version-Release number of selected component (if applicable):

matrix-synapse-1.51.0-1 +
matrix-synapse-1.52.0-1

Last working:

matrix-synapse-1.49.2-1


LOGFILES:

2022-02-09 00:00:11,871 - synapse.federation.transport.server.federation - 114 - ERROR - PUT-34436 - 'dict' object has no attribute 'edu_type'
Traceback (most recent call last):
  File "/usr/lib/python3.9/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/lib/python3.9/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: {'ed25519:a_yYZc': FetchKeyResult(verify_key=<nacl.signing.VerifyKey object at 0x7fc8a42f3430>, valid_until_ts=1644405109409)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/synapse/federation/transport/server/federation.py", line 101, in on_PUT
    device_list_updates = [
  File "/usr/lib/python3.9/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'




2022-02-09 00:00:41,933 - synapse.federation.transport.server.federation - 114 - ERROR - PUT-34443 - 'dict' object has no attribute 'edu_type'
Traceback (most recent call last):
  File "/usr/lib/python3.9/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/lib/python3.9/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: {'ed25519:a_iiuD': FetchKeyResult(verify_key=<nacl.signing.VerifyKey object at 0x7fc8a5af6d90>, valid_until_ts=1644443665400)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/synapse/federation/transport/server/federation.py", line 101, in on_PUT
    device_list_updates = [
  File "/usr/lib/python3.9/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'



2022-02-09 00:00:48,355 - synapse.federation.transport.server.federation - 114 - ERROR - PUT-34446 - 'dict' object has no attribute 'edu_type'
Traceback (most recent call last):
  File "/usr/lib/python3.9/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/lib/python3.9/site-packages/twisted/internet/defer.py", line 1661, in _inlineCallbacks
    result = current_context.run(gen.send, result)
StopIteration: {'ed25519:a_yYZc': FetchKeyResult(verify_key=<nacl.signing.VerifyKey object at 0x7fc8a42f3430>, valid_until_ts=1644405109409)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/synapse/federation/transport/server/federation.py", line 101, in on_PUT
    device_list_updates = [
  File "/usr/lib/python3.9/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'

Comment 1 Kai A. Hiller 2022-02-09 15:39:00 UTC
It seems another homeserver your Synapse is federating with is misbehaving. Your logs suggest you’re receiving invalid EDUs without the required `edu_type` field. External messages are probably broken because EDUs are required for encryption.

The failing code was introduced in v1.51.0 for debugging purposes only. I’ll coordinate with upstream for a fix.

As a quick workaround, you can disable the Python logger with the name "synapse.8631_debug". Bonus points if you can identify the misbehaving server and figure out its implementation and version.

Comment 2 customercare 2022-02-09 16:00:08 UTC
to make it clear, EVERY EXTERNAL MSG is not received, even in multipersonrooms.

I treid a befriended server in our data center,
matrix.org itself.

both had the same issues sendto to my homeserver, untill i downgraded. After downgrade, the incoming message numbers exploded :D

Comment 3 Fedora Update System 2022-02-09 18:23:34 UTC
FEDORA-2022-82e695c840 has been submitted as an update to Fedora 34. https://bodhi.fedoraproject.org/updates/FEDORA-2022-82e695c840

Comment 4 Fedora Update System 2022-02-09 18:24:17 UTC
FEDORA-2022-cf3f74e2a8 has been submitted as an update to Fedora 35. https://bodhi.fedoraproject.org/updates/FEDORA-2022-cf3f74e2a8

Comment 5 Kai A. Hiller 2022-02-09 18:27:02 UTC
There is already a fix for the problem upstream that will be included in their next release: https://github.com/matrix-org/synapse/commit/dd7f825118f1b8f2789eee9498912ce362a79224

I backported it for the Fedora package and made a new release for you: https://bodhi.fedoraproject.org/updates/FEDORA-2022-82e695c840

Comment 6 customercare 2022-02-09 18:42:09 UTC
I don't see any Logger enabled:

# grep synapse.8631 *yaml
# grep synapse.8631 *config


I will just wait for the fix and see, if it helps :D

Comment 7 Kai A. Hiller 2022-02-09 19:11:14 UTC
For the record, it is enough to set the log level higher than DEBUG to not use that code path. So, in *log.config this should do the trick:

```
loggers:
    synapse.8631_debug:
        level: INFO
```

Comment 8 customercare 2022-02-09 20:22:12 UTC
confirmed, but it's odd, that there is a default entry for this logger, which is set to DEBUG internally.

Comment 9 Fedora Update System 2022-02-10 02:43:16 UTC
FEDORA-2022-82e695c840 has been pushed to the Fedora 34 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2022-82e695c840`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2022-82e695c840

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 10 Fedora Update System 2022-02-10 02:57:15 UTC
FEDORA-2022-cf3f74e2a8 has been pushed to the Fedora 35 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2022-cf3f74e2a8`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2022-cf3f74e2a8

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 11 Fedora Update System 2022-02-18 01:13:20 UTC
FEDORA-2022-82e695c840 has been pushed to the Fedora 34 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 12 Fedora Update System 2022-02-18 01:37:24 UTC
FEDORA-2022-cf3f74e2a8 has been pushed to the Fedora 35 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.