Synapse with workers: invalid command USER_SYNC

[Terbium-135]

Description

After updating to the latest dev build each and every worker log as well as the homeserver log is filled with that kind of error.

Am I missing something?

2020-04-09 17:19:09,348 - synapse.replication.tcp.client - 71 - ERROR -  - Lost replication conn: <twisted.python.failure.Failure twisted.internet.error.ConnectionDone: Connection was closed cleanly.>
2020-04-09 17:19:09,658 - synapse.replication.tcp.protocol - 223 - ERROR -  - [anon-hWrDh] invalid command USER_SYNC
2020-04-09 17:19:09,659 - synapse.replication.tcp.protocol - 280 - WARNING -  - [anon-hWrDh] Closing connection
2020-04-09 17:19:09,662 - synapse.replication.tcp.client - 71 - ERROR -  - Lost replication conn: <twisted.python.failure.Failure twisted.internet.error.ConnectionDone: Connection was closed cleanly.>
2020-04-09 17:19:09,952 - synapse.replication.tcp.protocol - 223 - ERROR -  - [anon-IAxdO] invalid command USER_SYNC
2020-04-09 17:19:09,953 - synapse.replication.tcp.protocol - 280 - WARNING -  - [anon-IAxdO] Closing connection
2020-04-09 17:19:09,956 - synapse.replication.tcp.client - 71 - ERROR -  - Lost replication conn: <twisted.python.failure.Failure twisted.internet.error.ConnectionDone: Connection was closed cleanly.>
2020-04-09 17:19:10,338 - synapse.replication.tcp.protocol - 223 - ERROR -  - [anon-ArViJ] invalid command USER_SYNC

Steps to reproduce

• getting latest dev branch
• using worker setup
• starting homeserver and workers using synctl command

Version information

• Version: homeserver.py version 1.12.3 (b=develop,967f99b9f)

• Install method: git pull

• Platform: Debian / Arm64

[richvdh]

have you restarted all your workers?

[Terbium-135]

Yes - using the following command:
synctl restart; synctl -a ./workers restart

[richvdh]

that's a slightly different question. Have you checked that all of the process have restarted by looking for a "STARTING" line in the logs?

[Terbium-135]

Yes, I did. And I also checked for any orphaned running synapse processes on that debian system.
Still a bit lost but no rush. It looks like I am the only one so far.
homeserver.log:

2020-04-09 15:03:46,322 - twisted - 192 - INFO - None - Redirected stdout/stderr to logs
2020-04-09 15:03:46,323 - root - 257 - WARNING - None - ***** STARTING SERVER *****
2020-04-09 15:03:46,323 - root - 258 - WARNING - None - Server /opt/synapse/synapse/synapse/app/homeserver.py version 1.12.3 (b=develop,967f99b9f)
2020-04-09 15:03:46,324 - root - 259 - INFO - None - Server hostname: XXX
2020-04-09 15:03:46,324 - synapse.app.homeserver - 355 - INFO - None - Setting up server
2020-04-09 15:03:46,325 - synapse.server - 260 - INFO - None - Setting up.
2020-04-09 15:03:46,389 - synapse.storage.data_stores - 48 - INFO - None - Preparing database 'master'...
2020-04-09 15:03:46,403 - synapse.storage.prepare_database - 320 - INFO - None - Upgrading schema to v58
2020-04-09 15:03:46,417 - synapse.storage.data_stores - 58 - INFO - None - Starting 'main' data store 

As an example - federations_sender.log:

2020-04-09 15:04:29,867 - twisted - 192 - INFO - None - Redirected stdout/stderr to logs
2020-04-09 15:04:29,868 - root - 257 - WARNING - None - ***** STARTING SERVER *****
2020-04-09 15:04:29,869 - root - 258 - WARNING - None - Server /opt/synapse/synapse/synapse/app/federation_sender.py version 1.12.3 (b=develop,967f99b9f)
2020-04-09 15:04:29,869 - root - 259 - INFO - None - Server hostname: XXX
2020-04-09 15:04:30,151 - synapse.app.federation_sender - 245 - WARNING -  - Starting daemon.
2020-04-09 15:04:30,651 - synapse.replication.tcp.protocol - 223 - ERROR -  - [anon-TjljX] invalid command USER_SYNC
2020-04-09 15:04:30,652 - synapse.replication.tcp.protocol - 280 - WARNING -  - [anon-TjljX] Closing connection 

[richvdh]

Now I'm getting it too :/

[richvdh]

hopefully fixed by #7318