matrix federation stops working after upgrading to 6.12.0

[individual-it]

Description:

I've managed to setup the matrix federation on a virgin server with Rocket.Chat v 6.6.3 and the automated script from https://docs.rocket.chat/docs/deploy-a-federated-rocketchat-workspace-with-docker
But after upgrading to 6.12.0 it stops working

Steps to reproduce:

1. use the script of https://docs.rocket.chat/docs/deploy-a-federated-rocketchat-workspace-with-docker to setup rocket.chat and the matrix federation
2. use RC_IMAGE=registry.rocket.chat/rocketchat/rocket.chat:6.6.3 and ROCKETCHAT_IMAGE_TAG=6.6.3 in the .env file, because that is the last version that takes the federation config from the registration.yaml file as the setup script expects, see chore(federation-v2): do not load registration.yaml file in container #32012
3. finish all setup
4. try to message between a matrix server and Rocket.Chat
5. change the .env file to contain RC_IMAGE=registry.rocket.chat/rocketchat/rocket.chat:6.11.2 and ROCKETCHAT_IMAGE_TAG=6.11.2
6. try to message between a matrix server and Rocket.Chat, it still should work
7. change the .env file to contain RC_IMAGE=registry.rocket.chat/rocketchat/rocket.chat:6.12.0 and ROCKETCHAT_IMAGE_TAG=6.12.0
8. restart the server
9. go to the matrix Federation configuration and click Verify configuration
10. try to message between a matrix server and Rocket.Chat

Expected behavior:

Federation should still work

Actual behavior:

Message appears saying:
Configuration could only be partially verified, homeserver configuration looks good, failed to verify appservice configuration: received unknown status from homeserver, message: Bad Request

Server Setup Information:

• Version of Rocket.Chat Server: 6.12
• License Type: Starter
• Number of Users: 1
• Operating System: Ubuntu 24
• Deployment Method: docker
• Number of Running Instances: 1
• DB Replicaset Oplog: Enabled
• NodeJS Version: 14.21.3 - x64
• MongoDB Version: 5.0.28

Client Setup Information

• Desktop App or Browser Version: Firefox Browser 129
• Operating System: Ubuntu

Additional context

Relevant logs:

synapse-1             | 2024-09-10 06:44:23,607 - synapse.storage.databases.main.event_push_actions - 1305 - INFO - rotate_notifs-9 - Rotating notifications
synapse-1             | 2024-09-10 06:44:23,611 - synapse.storage.databases.main.event_push_actions - 1528 - INFO - rotate_notifs-9 - Rotating notifications up to: 9
synapse-1             | 2024-09-10 06:44:23,616 - synapse.storage.databases.main.event_push_actions - 1627 - INFO - rotate_notifs-9 - Rotating notifications, handling 0 rows
synapse-1             | 2024-09-10 06:44:23,627 - synapse.storage.databases.main.event_push_actions - 1720 - INFO - rotate_notifs-9 - Rotating notifications, deleted 0 push actions
synapse-1             | 2024-09-10 06:44:23,771 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-9 - Dropped 0 items from caches
synapse-1             | 2024-09-10 06:44:24,010 - synapse.storage.databases.main.metrics - 475 - INFO - generate_user_daily_visits-0 - Calling _generate_user_daily_visits
synapse-1             | 2024-09-10 06:44:24,015 - synapse.app.homeserver - 64 - INFO - phone_stats_home-0 - Gathering stats for reporting
synapse-1             | 2024-09-10 06:44:24,094 - synapse.app.homeserver - 156 - INFO - phone_stats_home-0 - Reporting stats to https://matrix.org/report-usage-stats/push: {'memory_rss': 118856, 'cpu_average': 1, 'homeserver': 'chat.in-nepal.de', 'server_context': None, 'timestamp': 1725965064, 'uptime_seconds': 301, 'python_version': '3.9.15', 'total_users': 2, 'total_nonbridged_users': 2, 'daily_user_type_native': 2, 'daily_user_type_guest': 0, 'daily_user_type_bridged': 0, 'total_room_count': 2, 'daily_active_users': 0, 'monthly_active_users': 0, 'daily_active_e2ee_rooms': 0, 'daily_e2ee_messages': 0, 'daily_sent_e2ee_messages': 0, 'daily_active_rooms': 2, 'daily_messages': 3, 'daily_sent_messages': 2, 'r30_users_all': 0, 'r30v2_users_ios': 0, 'r30v2_users_android': 0, 'r30v2_users_web': 0, 'r30v2_users_electron': 0, 'r30v2_users_all': 0, 'cache_factor': 0.5, 'event_cache_size': 10240, 'database_engine': 'psycopg2', 'database_server_version': '14.13', 'log_level': 'INFO'}
synapse-1             | 2024-09-10 06:44:24,219 - synapse.http.client - 460 - INFO - phone_stats_home-0 - Received response to PUT https://matrix.org/report-usage-stats/push: 200
synapse-1             | 2024-09-10 06:44:25,366 - synapse.http.server - 108 - INFO - POST-29 - <XForwardedForRequest at 0x75e3f4f34b50 method='POST' uri='/_matrix/client/v1/appservice/rocketchat_87f0d8b399d2838f2c4d7ac49921e593755b2496/ping' clientproto='HTTP/1.1' site='8008'> SynapseError: 400 - Unrecognized request
synapse-1             | 2024-09-10 06:44:25,371 - synapse.access.http.8008 - 460 - INFO - POST-29 - ::ffff:172.18.0.10 - 8008 - {None} Processed request: 0.003sec/0.003sec (0.004sec, 0.000sec) (0.000sec/0.000sec/0) 59B 400 "POST /_matrix/client/v1/appservice/rocketchat_87f0d8b399d2838f2c4d7ac49921e593755b2496/ping HTTP/1.1" "-" [0 dbevts]
rocketchat-1          | MatrixHttpClient (REQ-4) { errcode: 'M_UNRECOGNIZED', error: 'Unrecognized request' }
synapse-1             | 2024-09-10 06:44:25,586 - synapse.access.http.8008 - 460 - INFO - GET-30 - 94.237.61.73 - 8008 - {None} Processed request: 0.001sec/0.002sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 48B 200 "GET /_matrix/federation/v1/version HTTP/1.1" "Go-http-client/2.0" [0 dbevts]

Sending a message from Rocket.Chat gives this log output:

rocketchat-1          | {"level":50,"time":"2024-09-11T03:41:01.764Z","pid":9,"hostname":"bade0ddcfb93","name":"System","msg":"Error sending message:","err":{"type":"FederationMatrixInvalidConfigurationError","message":"Federation configuration is invalid,unable to send message","stack":"FederationMatrixInvalidConfiguration: Federation configuration is invalid,unable to send message\n    at server/services/messages/service.ts:174:10\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40\n => awaited here:\n    at Function.Promise.await (/app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)\n    at app/lib/server/functions/sendMessage.ts:259:9\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40\n => awaited here:\n    at Function.Promise.await (/app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)\n    at app/lib/server/methods/sendMessage.ts:96:3\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40","name":"FederationMatrixInvalidConfiguration"}}
synapse-1             | 2024-09-10 23:41:02,231 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-3 - TX [openproject.org] {1726025701665} Sending transaction [1726025701665], (PDUs: 0, EDUs: 1)
synapse-1             | 2024-09-10 23:41:02,242 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-7 - Streaming: typing -> 4
synapse-1             | 2024-09-10 23:41:02,256 - synapse.access.http.8008 - 460 - INFO - PUT-41 - ::ffff:172.18.0.10 - 8008 - {@artur:chat.in-nepal.de} Processed request: 0.023sec/0.009sec (0.005sec, 0.000sec) (0.001sec/0.001sec/1) 2B 200 "PUT /_matrix/client/r0/rooms/!klMRxtbTcpLrvUOFnQ%3Aopenproject.org/typing/%40artur%3Achat.in-nepal.de?user_id=%40artur%3Achat.in-nepal.de HTTP/1.1" "-" [0 dbevts]
synapse-1             | 2024-09-10 23:41:02,269 - synapse.access.http.8008 - 460 - INFO - PUT-42 - ::ffff:172.18.0.10 - 8008 - {@artur:chat.in-nepal.de} Processed request: 0.012sec/0.003sec (0.006sec, 0.000sec) (0.004sec/0.004sec/1) 2B 200 "PUT /_matrix/client/r0/rooms/!klMRxtbTcpLrvUOFnQ%3Aopenproject.org/typing/%40artur%3Achat.in-nepal.de?user_id=%40artur%3Achat.in-nepal.de HTTP/1.1" "-" [0 dbevts]
rocketchat-1          | 172.18.0.1 - - [11/Sep/2024:03:41:02 +0000] "PUT /transactions/94?access_token=<REDACTED> HTTP/1.1" 200 2 "-" "Synapse/1.71.0"
rocketchat-1          |  false
synapse-1             | 2024-09-10 23:41:02,289 - synapse.http.client - 460 - INFO - as-sender-rocketchat_87f0d8b399d2838f2c4d7ac49921e593755b2496-4 - Received response to PUT http://172.17.0.1:3300/transactions/94?access_token=<redacted>: 200
synapse-1             | 2024-09-10 23:41:02,297 - synapse.http.matrixfederationclient - 299 - INFO - federation_transaction_transmission_loop-3 - {PUT-O-5} [openproject.org] Completed request: 200 OK in 0.06 secs, got 11 bytes - PUT matrix://openproject.org/_matrix/federation/v1/send/1726025701665
synapse-1             | 2024-09-10 23:41:02,298 - synapse.federation.sender.transaction_manager - 174 - INFO - federation_transaction_transmission_loop-3 - TX [openproject.org] {1726025701665} got 200 response

[reetp]

No idea about the rest of it but please note you should never use 'latest' here:

change the .env file to contain RC_IMAGE=registry.rocket.chat/rocketchat/rocket.chat:latest and ROCKETCHAT_IMAGE_TAG=latest

Always, always, always set a version and be in control. No nasty surprises then.

Have you tested on 6.11.x?

[individual-it]

@reetp you are right, I've updated the original comment to

1. set the tag to 6.12.0 and not to latest
2. confirm that 6.11.2 works correctly

I've tried every major version from 6.6 to 6.12 and can confirm that the problem only occurs in 6.12

[individual-it]

Digging deeper, Rocket.Chat 6.12 started to send pings to the homeserver to verify the configuration is correct, see https://github.com/RocketChat/Rocket.Chat/blob/develop/apps/meteor/server/services/federation/service.ts#L290
synapse seem to have a bug in the version that is used by the automated federation setup script (1.71.0), setting
SYNAPSE_IMAGE_TAG=v1.114.0 in the .env file allowed me at least to send messages from RC to Matrix

[individual-it]

I also could make it work in both directions with synapse 1.71 and rocket.chat 6.11.2
RC 6.11.2 does not work with newer versions of synapse (tried 1.89, 1.114), I believe the reason is that synapse is using the new matrix routes but Rocket.Chat the legacy once, see:

• https://spec.matrix.org/v1.9/application-service-api/#legacy-routes
• Call appservices on modern paths, falling back to legacy paths. matrix-org/synapse#15317
• Remove support for legacy application service paths matrix-org/synapse#15964

[reetp]

Don't need to @ people - I read it all.

Good test and thanks. Sure the team will be on it.

[individual-it]

One more observation: never versions of synapse using the Authorization header as described in https://spec.matrix.org/v1.11/application-service-api/#authorization ,but Rocket.Chat expects (as far as I can see) uses the token in a query parameter
Since 1.71 synapse is sending both, but since 1.90 this only happens if use_appservice_legacy_authorization is set to true
https://github.com/element-hq/synapse/blob/develop/docs/upgrade.md?plain=1#L160

[reetp]

FYI this has been passed to the internal teams for consideration.

[individual-it]

I might have been wrong about the legacy routes, the federation mostly works for me now after setting
use_appservice_legacy_authorization: true in homeserver.yaml