Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

synapse throw me out of #Matrix HQ because of an error resolving state for the room #7913

Closed
sbug-1bit opened this issue Jul 20, 2020 · 7 comments
Labels
A-Federation z-bug (Deprecated Label)

Comments

@sbug-1bit
Copy link

sbug-1bit commented Jul 20, 2020

Today I was once again thrown out of Matrix HQ.
I wounder if this could be the same bug still lurking around or a new one?

My synapse log file: http://1bit.se/wp-content/uploads/simple-file-list/homeserver_log.1
(Loglevel set to INFO)

At 11:05:47 in the logfile I see an error resolving state for the room matrix hq.
After that time I also no longer got any new events in the room in my client. And after clear cache and reload it was revealed to me that I had been thrown out of the room.

I use synapse 1.17.0

@anoadragon453
Copy link
Member

Looking through the logs, I see multiple instances of ERROR 403: Your server isn't divulging details about prev_events referenced in this event.:

2020-07-19 09:23:39,651 - synapse.http.matrixfederationclient - 442 - INFO - PUT-2255354-$159514324010Stqap:zlima12.com - Failed to send request: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]
2020-07-19 09:23:39,652 - synapse.http.matrixfederationclient - 507 - WARNING - PUT-2255354-$159514324010Stqap:zlima12.com - {POST-O-981545} [zlima12.com] Request failed: POST matrix://zlima12.com/_matrix/federation/v1/get_missing_events/%21zXfJBqSUvXySmsZMtB%3Ajki.re: ResponseNeverReceived:[ConnectionLost('Connection lost')]
2020-07-19 09:23:39,652 - synapse.util.retryutils - 218 - INFO - PUT-2255354-$159514324010Stqap:zlima12.com - Connection to zlima12.com was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>])); backoff now 600000
2020-07-19 09:23:39,654 - synapse.handlers.federation - 513 - WARNING - PUT-2255354-$159514324010Stqap:zlima12.com - [!zXfJBqSUvXySmsZMtB:jki.re $159514324010Stqap:zlima12.com]: Failed to get prev_events: Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]
2020-07-19 09:23:39,665 - synapse.handlers.federation - 324 - WARNING - PUT-2255354-$159514324010Stqap:zlima12.com - [!zXfJBqSUvXySmsZMtB:jki.re $159514324010Stqap:zlima12.com] Rejecting: failed to fetch 1 prev events: ['$15950132040fKnGU:zlima12.com']
2020-07-19 09:23:39,666 - synapse.federation.federation_server - 284 - WARNING - PUT-2255354-$159514324010Stqap:zlima12.com - Error handling PDU $159514324010Stqap:zlima12.com: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
2020-07-19 09:23:39,678 - synapse.access.http.8008 - 312 - INFO - GET-2255384 - 90.231.171.88 - 8008 - {@sbug:1bit.se} Processed request: 0.410sec/0.001sec (0.009sec, 0.000sec) (0.005sec/0.004sec/1) 1759B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s421135_1287771_62643_132685_920_46_31_232746_1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element(Riot)/1.7.1 Chrome/83.0.4103.119 Electron/9.0.5 Safari/537.36" [0 dbevts]
2020-07-19 09:23:39,681 - synapse.access.http.8008 - 312 - INFO - PUT-2255354 - 98.116.111.96 - 8008 - {zlima12.com} Processed request: 3.336sec/0.001sec (0.023sec, 0.001sec) (0.005sec/0.042sec/9) 149B 200 "PUT /_matrix/federation/v1/send/1595039269234 HTTP/1.0" "Synapse/1.15.2" [1 dbevts]

and

2020-07-19 13:45:35,110 - synapse.http.federation.matrix_federation_agent - 250 - INFO - federation_transaction_transmission_loop-1080055 - Connecting to matrix.zlima12.com:443
2020-07-19 13:45:35,309 - synapse.http.matrixfederationclient - 442 - INFO - PUT-2345769-$pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY - Failed to send request: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]
2020-07-19 13:45:35,310 - synapse.http.matrixfederationclient - 507 - WARNING - PUT-2345769-$pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY - {POST-O-1013194} [zlima12.com] Request failed: POST matrix://zlima12.com/_matrix/federation/v1/get_missing_events/%21YTvKGNlinIzlkMTVRl%3Amatrix.org: ResponseNeverReceived:[ConnectionLost('Connection lost')]
2020-07-19 13:45:35,310 - synapse.util.retryutils - 218 - INFO - PUT-2345769-$pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY - Connection to zlima12.com was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>])); backoff now 600000
2020-07-19 13:45:35,311 - synapse.handlers.federation - 513 - WARNING - PUT-2345769-$pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY - [!YTvKGNlinIzlkMTVRl:matrix.org $pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY]: Failed to get prev_events: Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]
2020-07-19 13:45:35,316 - synapse.handlers.federation - 324 - WARNING - PUT-2345769-$pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY - [!YTvKGNlinIzlkMTVRl:matrix.org $pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY] Rejecting: failed to fetch 1 prev events: ['$smeu53Im6i0AfmlMcFrJhwPmx5rgEWlEgMhDBxr0tVE']
2020-07-19 13:45:35,316 - synapse.federation.federation_server - 284 - WARNING - PUT-2345769-$pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY - Error handling PDU $pdsz8IUtYIz69NyL7YyvkfW_zSDZJCjJwf6OyQyGTVY: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
2020-07-19 13:45:35,323 - synapse.access.http.8008 - 312 - INFO - PUT-2345769 - 98.116.111.96 - 8008 - {zlima12.com} Processed request: 3.321sec/0.001sec (0.019sec, 0.001sec) (0.004sec/0.014sec/7) 163B 200 "PUT /_matrix/federation/v1/send/1595039276602 HTTP/1.0" "Synapse/1.15.2" [1 dbevts]

A full trace would be:

2020-07-19 11:06:11,321 - synapse.federation.transport.server - 402 - INFO - PUT-2287069 - Received txn 1595039271599 from zlima12.com. (PDUs: 1, EDUs: 1)
2020-07-19 11:06:11,381 - synapse.handlers.federation - 177 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - handling received PDU: <FrozenEventV3 event_id='$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04', type='m.room.member', state_key='@john:zlima12.com'>
2020-07-19 11:06:11,422 - synapse.handlers.federation - 262 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - [!mjbDjyNsRXndKLkHIe:matrix.org $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04] Acquiring room lock to fetch 2 missing prev_events: ['$byy5-iplGBOQvNjK1F4_-a7uT-XIAiMxtldx69iJXhc', '$G1zJBAlmPweFtp4WiokemVdXJRNbRTzZteOXYNBSZcA']
2020-07-19 11:06:11,422 - synapse.handlers.federation - 269 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - [!mjbDjyNsRXndKLkHIe:matrix.org $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04] Acquired room lock to fetch 2 missing prev_events
2020-07-19 11:06:11,440 - synapse.handlers.federation - 447 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - [!mjbDjyNsRXndKLkHIe:matrix.org $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04]: Requesting missing events between ['$ECjAs4MTIaqL8rooH-bDm0-HWD7M_tXekJ5T4IQQn9M', '$u0FtR6wr97g1DxKgthPrh5bIkfjlL61Un2g-kkJ0RO4', '$zjntoQRsA7AZJn6McpL-xs3_JjYKRllbU7mP5E_dWiE', '$0e2o1vUx_O3Mf1WDxYKQPHHqkHmfDubeS1mj26sKCFY'] and $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04
2020-07-19 11:06:11,440 - synapse.http.matrixfederationclient - 414 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - {POST-O-998949} [zlima12.com] Sending request: POST matrix://zlima12.com/_matrix/federation/v1/get_missing_events/%21mjbDjyNsRXndKLkHIe%3Amatrix.org; timeout 60.000000s
2020-07-19 11:06:11,441 - synapse.http.federation.matrix_federation_agent - 250 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - Connecting to matrix.zlima12.com:443
2020-07-19 11:06:40,933 - synapse.http.matrixfederationclient - 442 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - Failed to send request: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]
2020-07-19 11:06:40,933 - synapse.http.matrixfederationclient - 507 - WARNING - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - {POST-O-998949} [zlima12.com] Request failed: POST matrix://zlima12.com/_matrix/federation/v1/get_missing_events/%21mjbDjyNsRXndKLkHIe%3Amatrix.org: ResponseNeverReceived:[ConnectionLost('Connection lost')]
2020-07-19 11:06:40,933 - synapse.util.retryutils - 218 - INFO - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - Connection to zlima12.com was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>])); backoff now 600000
2020-07-19 11:06:40,934 - synapse.handlers.federation - 513 - WARNING - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - [!mjbDjyNsRXndKLkHIe:matrix.org $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04]: Failed to get prev_events: Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.error.ConnectionLost: Connection to the other side was lost in a non-clean fashion: Connection lost.>]
2020-07-19 11:06:40,941 - synapse.handlers.federation - 324 - WARNING - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - [!mjbDjyNsRXndKLkHIe:matrix.org $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04] Rejecting: failed to fetch 2 prev events: ['$byy5-iplGBOQvNjK1F4_-a7uT-XIAiMxtldx69iJXhc', '$G1zJBAlmPweFtp4WiokemVdXJRNbRTzZteOXYNBSZcA']
2020-07-19 11:06:40,941 - synapse.federation.federation_server - 284 - WARNING - PUT-2287069-$nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04 - Error handling PDU $nrgXviLUiFY-IvHFZ_yju8LVQvNDaX80756WPT0ao04: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
2020-07-19 11:06:40,951 - synapse.access.http.8008 - 312 - INFO - PUT-2287069 - 98.116.111.96 - 8008 - {zlima12.com} Processed request: 29.639sec/0.001sec (0.021sec, 0.004sec) (0.043sec/0.052sec/12) 163B 200 "PUT /_matrix/federation/v1/send/1595039271599 HTTP/1.0" "Synapse/1.15.2" [2 dbevts]
~ ❯ grep "PUT-2286966" /tmp/mozilla_user0/homeserver.log.1                                                                                                                                                                                                                       14:54:13
2020-07-19 11:05:42,282 - synapse.federation.transport.server - 402 - INFO - PUT-2286966 - Received txn 1594977718663 from tchncs.de. (PDUs: 1, EDUs: 0)
2020-07-19 11:05:42,333 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - handling received PDU: <FrozenEventV3 event_id='$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw', type='m.room.message', state_key='None'>
2020-07-19 11:05:42,345 - synapse.handlers.federation - 262 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Acquiring room lock to fetch 1 missing prev_events: ['$2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU']
2020-07-19 11:05:42,346 - synapse.handlers.federation - 269 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Acquired room lock to fetch 1 missing prev_events
2020-07-19 11:05:42,349 - synapse.handlers.federation - 447 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw]: Requesting missing events between ['$IP20TfXc7HGr7ONCWtqxRspA0KqQQIaLmkkvl6X5fCg'] and $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw
2020-07-19 11:05:42,351 - synapse.http.matrixfederationclient - 414 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - {POST-O-997407} [tchncs.de] Sending request: POST matrix://tchncs.de/_matrix/federation/v1/get_missing_events/%21OGEhHVWSdvArJzumhm%3Amatrix.org; timeout 60.000000s
2020-07-19 11:05:42,353 - synapse.http.federation.matrix_federation_agent - 250 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - Connecting to tchncs.de:8448
2020-07-19 11:05:46,068 - synapse.http.matrixfederationclient - 163 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - {POST-O-997407} [tchncs.de] Completed: 200 OK
2020-07-19 11:05:46,075 - synapse.handlers.federation - 522 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw]: Got 10 prev_events: [<FrozenEventV3 event_id='$XpyjqLQjNsBIjuPppmpoMDmg54GJRVwrPaMuxWL1SSQ', type='m.room.message', state_key='None'>, <FrozenEventV3 event_id='$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg', type='m.room.message', state_key='None'>, <FrozenEventV3 event_id='$PZ81NdScsizpSIJIT4lb9DGKWvRA__w8eziGWRP9enA', type='m.room.message', state_key='None'>, <FrozenEventV3 event_id='$JdWjjMk5UK0U9M6Wx_kB2r6UWwxhnS8YpsSgH9A2tAc', type='m.room.message', state_key='None'>, <FrozenEventV3 event_id='$vxmOP0pRHy2m_Cdto__1NNGRdJehaKNli-LGtmUf6jQ', type='m.room.message', state_key='None'>, ...]
2020-07-19 11:05:46,075 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg
2020-07-19 11:05:46,075 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - handling received PDU: <FrozenEventV3 event_id='$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg', type='m.room.message', state_key='None'>
2020-07-19 11:05:46,078 - synapse.handlers.federation - 339 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - Event $ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg is missing prev_events: calculating state for a backwards extremity
2020-07-19 11:05:46,078 - synapse.handlers.federation - 359 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - Requesting state at missing prev_event $ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg
2020-07-19 11:05:46,078 - synapse.http.matrixfederationclient - 414 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg-$z4389liaANgOTs1qmkiII7LDnvXIhLfu2dUJ0z3brjc - {GET-O-997420} [tchncs.de] Sending request: GET matrix://tchncs.de/_matrix/federation/v1/state_ids/%21OGEhHVWSdvArJzumhm%3Amatrix.org?event_id=%24z4389liaANgOTs1qmkiII7LDnvXIhLfu2dUJ0z3brjc; timeout 60.000000s
2020-07-19 11:05:47,553 - synapse.http.matrixfederationclient - 466 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg-$z4389liaANgOTs1qmkiII7LDnvXIhLfu2dUJ0z3brjc - {GET-O-997420} [tchncs.de] Got response headers: 404 Not Found
2020-07-19 11:05:47,554 - synapse.http.matrixfederationclient - 542 - WARNING - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg-$z4389liaANgOTs1qmkiII7LDnvXIhLfu2dUJ0z3brjc - {GET-O-997420} [tchncs.de] Request failed: GET matrix://tchncs.de/_matrix/federation/v1/state_ids/%21OGEhHVWSdvArJzumhm%3Amatrix.org?event_id=%24z4389liaANgOTs1qmkiII7LDnvXIhLfu2dUJ0z3brjc: HttpResponseException("404: b'Not Found'")
2020-07-19 11:05:47,555 - synapse.handlers.federation - 407 - WARNING - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - [!OGEhHVWSdvArJzumhm:matrix.org $ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg] Error attempting to resolve state at missing prev_events
2020-07-19 11:05:47,556 - synapse.handlers.federation - 545 - WARNING - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Received prev_event $ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg failed history check.
2020-07-19 11:05:47,556 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674
2020-07-19 11:05:47,557 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674 - handling received PDU: <FrozenEventV3 event_id='$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674', type='m.room.message', state_key='None'>
2020-07-19 11:05:47,560 - synapse.handlers.federation - 339 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674 - Event $7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674 is missing prev_events: calculating state for a backwards extremity
2020-07-19 11:05:47,561 - synapse.handlers.federation - 359 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674 - Requesting state at missing prev_event $7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674
2020-07-19 11:05:47,561 - synapse.http.matrixfederationclient - 414 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - {GET-O-997421} [tchncs.de] Sending request: GET matrix://tchncs.de/_matrix/federation/v1/state_ids/%21OGEhHVWSdvArJzumhm%3Amatrix.org?event_id=%24ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg; timeout 60.000000s
2020-07-19 11:05:49,232 - synapse.http.matrixfederationclient - 163 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - {GET-O-997421} [tchncs.de] Completed: 200 OK
2020-07-19 11:05:49,243 - synapse.http.matrixfederationclient - 414 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - {GET-O-997422} [tchncs.de] Sending request: GET matrix://tchncs.de/_matrix/federation/v1/event/%24ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg; timeout 60.000000s
2020-07-19 11:05:50,524 - synapse.http.matrixfederationclient - 163 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - {GET-O-997422} [tchncs.de] Completed: 200 OK
2020-07-19 11:05:50,528 - synapse.handlers.federation - 2338 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg-$ucWEzHZLdZ0IjojmIxb9MdJ8_Y0jGm6l_5WIMFGxPQg - Skipping auth_event fetch for outlier
2020-07-19 11:05:50,727 - synapse.state - 408 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$7CJFlCOP2ESM1rMVPu1_fpQ28yrv9SFV4uv0xb9m674 - Resolving state for !OGEhHVWSdvArJzumhm:matrix.org with 2 groups
2020-07-19 11:06:27,498 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $xRWlkdZHyd3w0A6aoS2nfbCYjFT1f_e5Zt3eegLXjqg
2020-07-19 11:06:27,499 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$xRWlkdZHyd3w0A6aoS2nfbCYjFT1f_e5Zt3eegLXjqg - handling received PDU: <FrozenEventV3 event_id='$xRWlkdZHyd3w0A6aoS2nfbCYjFT1f_e5Zt3eegLXjqg', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,501 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$xRWlkdZHyd3w0A6aoS2nfbCYjFT1f_e5Zt3eegLXjqg - [!OGEhHVWSdvArJzumhm:matrix.org $xRWlkdZHyd3w0A6aoS2nfbCYjFT1f_e5Zt3eegLXjqg] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,501 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $XpyjqLQjNsBIjuPppmpoMDmg54GJRVwrPaMuxWL1SSQ
2020-07-19 11:06:27,501 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$XpyjqLQjNsBIjuPppmpoMDmg54GJRVwrPaMuxWL1SSQ - handling received PDU: <FrozenEventV3 event_id='$XpyjqLQjNsBIjuPppmpoMDmg54GJRVwrPaMuxWL1SSQ', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,504 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$XpyjqLQjNsBIjuPppmpoMDmg54GJRVwrPaMuxWL1SSQ - [!OGEhHVWSdvArJzumhm:matrix.org $XpyjqLQjNsBIjuPppmpoMDmg54GJRVwrPaMuxWL1SSQ] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,505 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $PZ81NdScsizpSIJIT4lb9DGKWvRA__w8eziGWRP9enA
2020-07-19 11:06:27,505 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$PZ81NdScsizpSIJIT4lb9DGKWvRA__w8eziGWRP9enA - handling received PDU: <FrozenEventV3 event_id='$PZ81NdScsizpSIJIT4lb9DGKWvRA__w8eziGWRP9enA', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,509 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$PZ81NdScsizpSIJIT4lb9DGKWvRA__w8eziGWRP9enA - [!OGEhHVWSdvArJzumhm:matrix.org $PZ81NdScsizpSIJIT4lb9DGKWvRA__w8eziGWRP9enA] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,509 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $JdWjjMk5UK0U9M6Wx_kB2r6UWwxhnS8YpsSgH9A2tAc
2020-07-19 11:06:27,510 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$JdWjjMk5UK0U9M6Wx_kB2r6UWwxhnS8YpsSgH9A2tAc - handling received PDU: <FrozenEventV3 event_id='$JdWjjMk5UK0U9M6Wx_kB2r6UWwxhnS8YpsSgH9A2tAc', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,512 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$JdWjjMk5UK0U9M6Wx_kB2r6UWwxhnS8YpsSgH9A2tAc - [!OGEhHVWSdvArJzumhm:matrix.org $JdWjjMk5UK0U9M6Wx_kB2r6UWwxhnS8YpsSgH9A2tAc] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,513 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $vxmOP0pRHy2m_Cdto__1NNGRdJehaKNli-LGtmUf6jQ
2020-07-19 11:06:27,513 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$vxmOP0pRHy2m_Cdto__1NNGRdJehaKNli-LGtmUf6jQ - handling received PDU: <FrozenEventV3 event_id='$vxmOP0pRHy2m_Cdto__1NNGRdJehaKNli-LGtmUf6jQ', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,514 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$vxmOP0pRHy2m_Cdto__1NNGRdJehaKNli-LGtmUf6jQ - [!OGEhHVWSdvArJzumhm:matrix.org $vxmOP0pRHy2m_Cdto__1NNGRdJehaKNli-LGtmUf6jQ] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,514 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $KQtuMJdvIi8cgs7JyxETzy9XjZQQBq2RUKrfKEeDPRM
2020-07-19 11:06:27,514 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$KQtuMJdvIi8cgs7JyxETzy9XjZQQBq2RUKrfKEeDPRM - handling received PDU: <FrozenEventV3 event_id='$KQtuMJdvIi8cgs7JyxETzy9XjZQQBq2RUKrfKEeDPRM', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,516 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$KQtuMJdvIi8cgs7JyxETzy9XjZQQBq2RUKrfKEeDPRM - [!OGEhHVWSdvArJzumhm:matrix.org $KQtuMJdvIi8cgs7JyxETzy9XjZQQBq2RUKrfKEeDPRM] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,516 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I
2020-07-19 11:06:27,516 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I - handling received PDU: <FrozenEventV3 event_id='$86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I', type='m.room.message', state_key='None'>
2020-07-19 11:06:27,518 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I - [!OGEhHVWSdvArJzumhm:matrix.org $86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,518 - synapse.handlers.federation - 534 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Handling received prev_event $2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU
2020-07-19 11:06:27,518 - synapse.handlers.federation - 177 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU - handling received PDU: <FrozenEventV3 event_id='$2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU', type='m.room.member', state_key='@porcospino:matrix.drycat.fr'>
2020-07-19 11:06:27,520 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU - [!OGEhHVWSdvArJzumhm:matrix.org $2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU] Ignoring PDU from tchncs.de as we're not in the room
2020-07-19 11:06:27,523 - synapse.handlers.federation - 324 - WARNING - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - [!OGEhHVWSdvArJzumhm:matrix.org $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw] Rejecting: failed to fetch 1 prev events: ['$2GC8uxo0-7X2X7aqKEubL1QADEs4lXCHX_Vvt8UyHaU']
2020-07-19 11:06:27,523 - synapse.federation.federation_server - 284 - WARNING - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw - Error handling PDU $8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
2020-07-19 11:06:27,527 - synapse.access.http.8008 - 312 - INFO - PUT-2286966 - 195.201.167.148 - 8008 - {tchncs.de} Processed request: 45.251sec/0.000sec (3.198sec, 0.016sec) (0.019sec/0.668sec/17) 163B 200 "PUT /_matrix/federation/v1/send/1594977718663 HTTP/1.0" "Synapse/1.17.0" [14910 dbevts]

I initially wondered if the remote servers associated with the errors in your logs (zlima12.com, synapse.duncanturk.com, tchncs.de) were running old versions of Synapse, but both synapse.duncanturk.com and tchncs.de are on v1.17.0 (as of checking now), and zlima12.com is on v1.15.2 which is when the fix for #7742 came out.

Your server does seem to believe it's not in the room however, as evidenced by log lines like:

2020-07-19 11:06:27,518 - synapse.handlers.federation - 230 - INFO - PUT-2286966-$8e9ouApkgucswykOOABugI3xBP2fFNdGtpl89INKNvw-$86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I - [!OGEhHVWSdvArJzumhm:matrix.org $86BLkspYmpPyyF7jqCL9cgIixekvZqQJz-S6rj3pc2I] Ignoring PDU from tchncs.de as we're not in the room

@richvdh @erikjohnston do you know if there is any manual cleanup required for homeservers to do if they were affected by #7742?

@richvdh
Copy link
Member

richvdh commented Jul 21, 2020

@richvdh @erikjohnston do you know if there is any manual cleanup required for homeservers to do if they were affected by #7742?

I've got a horrible feeling that once your server has reached incorrect conclusions about room state as a result of #7742, those incorrect conclusions will tend to persist for the lifetime of the room. The only solution to that would be to leave the room, purge it from the database, and rejoin. However I haven't studied this in depth, and @erikjohnston is the authority here. It may be best to await his return.

@ZLima12
Copy link

ZLima12 commented Jul 23, 2020

I own zlima12.com, and can provide any information that might be useful. Doesn't seem like the logs here say too much about what went wrong in the interaction with my homeserver though.

@verymilan
Copy link

verymilan commented Nov 24, 2020

I also have a long list of rooms with this kind of error in my logs, i've just realized. Could this be related to unreferenced state groups? tchncs.de here btw

@erikjohnston
Copy link
Member

This will have been due to a state reset, the causes of which we've been slowly resolving

@DMRobertson
Copy link
Contributor

Related: #8629

@catfromplan9
Copy link

catfromplan9 commented May 27, 2023

This will have been due to a state reset, the causes of which we've been slowly resolving

Please try to fix this soon, or I might just have to uninstall synapse and revert to email. I really like matrix but this bug is making it so hard to use.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A-Federation z-bug (Deprecated Label)
Projects
None yet
Development

No branches or pull requests

8 participants