I run into this pretty consistently, and it's annoyed me to the point where I want to investigate it.

I found some logs from a bad test run, in server-0's homeserver.log:

2020-04-12 16:02:07,716 - synapse.replication.http.send_event - 119 - INFO - POST-1176 - Got event to send with ID: $Wyh5zl914K2GIfm3X9WIN5xRp1CSK7q6RMz5RXqVsEQ into room: !UJfEiVhWyjgjLYLDjv:localhost:8831
2020-04-12 16:02:07,733 - synapse.access.http.8801 - 301 - INFO - POST-1176 - 127.0.0.1 - 8801 - {@anon-20200412_155942-173:localhost:8831} Processed request: 0.016sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "POST /_synapse/replication/send_event/%24Wyh5zl914K2GIfm3X9WIN5xRp1CSK7q6RMz5RXqVsEQ/LetjjSSVwI HTTP/1.1" "Synapse/1.12.3 homeserver[0]" [0 dbevts]
2020-04-12 16:02:07,742 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1443 - Streaming: events -> 775
2020-04-12 16:02:07,870 - synapse.access.http.8801 - 301 - INFO - PUT-1177 - 127.0.0.1 - 8801 - {@anon-20200412_155942-173:localhost:8831} Processed request: 0.037sec/0.000sec (0.005sec, 0.002sec) (0.002sec/0.006sec/4) 59B 200 "PUT /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.guest_access?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:07,877 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1444 - Streaming: caches -> 1365
2020-04-12 16:02:07,894 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1444 - Streaming: events -> 776
2020-04-12 16:02:07,956 - synapse.replication.http.send_event - 119 - INFO - POST-1178 - Got event to send with ID: $F_t8Jzte71HEfYW-bBM4pLqG26bNivEyJEt_1HV4k9E into room: !UJfEiVhWyjgjLYLDjv:localhost:8831
2020-04-12 16:02:07,987 - synapse.access.http.8801 - 301 - INFO - POST-1178 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.031sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.001sec/1) 2B 200 "POST /_synapse/replication/send_event/%24F_t8Jzte71HEfYW-bBM4pLqG26bNivEyJEt_1HV4k9E/oOLVSKmtSl HTTP/1.1" "Synapse/1.12.3 homeserver[0]" [0 dbevts]
2020-04-12 16:02:07,992 - synapse.replication.http.membership - 193 - INFO - POST-1179 - user membership change: @7:localhost:8831 in !UJfEiVhWyjgjLYLDjv:localhost:8831
2020-04-12 16:02:07,994 - synapse.access.http.8801 - 301 - INFO - POST-1179 - 127.0.0.1 - 8801 - {None} Processed request: 0.001sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "POST /_synapse/replication/membership_change/%21UJfEiVhWyjgjLYLDjv%3Alocalhost%3A8831/%407%3Alocalhost%3A8831/joined HTTP/1.1" "Synapse/1.12.3 homeserver[0]" [0 dbevts]
2020-04-12 16:02:07,996 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1445 - Streaming: caches -> 1366
2020-04-12 16:02:08,014 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1445 - Streaming: events -> 777
2020-04-12 16:02:08,056 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1446 - Streaming: federation -> 203
2020-04-12 16:02:08,078 - synapse.access.http.8801 - 301 - INFO - GET-1180 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.009sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.002sec/2) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:08,239 - synapse.access.http.8801 - 301 - INFO - GET-1181 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.002sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:08,471 - synapse.access.http.8801 - 301 - INFO - GET-1182 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.003sec/0.000sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:08,817 - synapse.access.http.8801 - 301 - INFO - GET-1183 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.003sec/0.000sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:09,331 - synapse.access.http.8801 - 301 - INFO - GET-1184 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.003sec/0.000sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:10,099 - synapse.access.http.8801 - 301 - INFO - GET-1185 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.004sec/0.000sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:11,075 - twisted - 192 - INFO -  - Timing out client: IPv4Address(type='TCP', host='127.0.0.1', port=57918)
2020-04-12 16:02:11,247 - synapse.access.http.8801 - 301 - INFO - GET-1186 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.004sec/0.000sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:12,965 - synapse.access.http.8801 - 301 - INFO - GET-1187 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.003sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:15,536 - synapse.access.http.8801 - 301 - INFO - GET-1188 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.004sec/0.000sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 72B 200 "GET /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.member/@7:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:17,016 - synapse.metrics - 464 - INFO -  - Collecting gc 1

The master process is notified that the user's membership changed in the room, but even requesting the state of the room 8 seconds later we still send back the old value.

Seeing as the event_creator is supposedly the one handling these /state/ requests, according to workers.md, I took a look at its logs and found the following:

2020-04-12 16:02:07,714 - synapse.http.client - 281 - INFO - POST-214 - Sending request POST http://localhost:8801/_synapse/replication/send_event/%24Wyh5zl914K2GIfm3X9WIN5xRp1CSK7q6RMz5RXqVsEQ/LetjjSSVwI
2020-04-12 16:02:07,739 - synapse.http.client - 318 - INFO - POST-214 - Received response to POST http://localhost:8801/_synapse/replication/send_event/%24Wyh5zl914K2GIfm3X9WIN5xRp1CSK7q6RMz5RXqVsEQ/LetjjSSVwI: 200
2020-04-12 16:02:07,741 - synapse.access.http.8825 - 301 - INFO - POST-214 - 127.0.0.1 - 8825 - {@anon-20200412_155942-173:localhost:8831} Processed request: 0.051sec/0.001sec (0.006sec, 0.002sec) (0.004sec/0.008sec/12) 59B 200 "POST /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/send/m.room.test?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:07,950 - synapse.http.client - 281 - INFO - POST-215 - Sending request POST http://localhost:8801/_synapse/replication/send_event/%24F_t8Jzte71HEfYW-bBM4pLqG26bNivEyJEt_1HV4k9E/oOLVSKmtSl
2020-04-12 16:02:07,989 - synapse.http.client - 318 - INFO - POST-215 - Received response to POST http://localhost:8801/_synapse/replication/send_event/%24F_t8Jzte71HEfYW-bBM4pLqG26bNivEyJEt_1HV4k9E/oOLVSKmtSl: 200
2020-04-12 16:02:07,990 - synapse.http.client - 281 - INFO - POST-215 - Sending request POST http://localhost:8801/_synapse/replication/membership_change/%21UJfEiVhWyjgjLYLDjv%3Alocalhost%3A8831/%407%3Alocalhost%3A8831/joined
2020-04-12 16:02:07,996 - synapse.http.client - 318 - INFO - POST-215 - Received response to POST http://localhost:8801/_synapse/replication/membership_change/%21UJfEiVhWyjgjLYLDjv%3Alocalhost%3A8831/%407%3Alocalhost%3A8831/joined: 200
2020-04-12 16:02:07,997 - synapse.access.http.8825 - 301 - INFO - POST-215 - 127.0.0.1 - 8825 - {@7:localhost:8831} Processed request: 0.121sec/0.001sec (0.027sec, 0.001sec) (0.014sec/0.025sec/17) 48B 200 "POST /_matrix/client/r0/join/!UJfEiVhWyjgjLYLDjv:localhost:8831?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [1 dbevts]

It receives the membership change and the profile requests, but it doesn't seem to be receiving the /state/ ones...

At this point I realised it was the main homeserver process that was handling these requests. Which is fine, but it's odd that the main process, which logs that it receives the membership update for the room, would still be responding with the old displayname...

However, I did notice that in homeserver.log there is a request for the state of that room just before the membership change:

2020-04-12 16:02:07,870 - synapse.access.http.8801 - 301 - INFO - PUT-1177 - 127.0.0.1 - 8801 - {@anon-20200412_155942-173:localhost:8831} Processed request: 0.037sec/0.000sec (0.005sec, 0.002sec) (0.002sec/0.006sec/4) 59B 200 "PUT /_matrix/client/r0/rooms/!UJfEiVhWyjgjLYLDjv:localhost:8831/state/m.room.guest_access?access_token=<redacted> HTTP/1.1" "Perl + Net::Async::HTTP/0.45" [0 dbevts]
2020-04-12 16:02:07,877 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1444 - Streaming: caches -> 1365
2020-04-12 16:02:07,894 - synapse.replication.tcp.resource - 178 - INFO - replication_notifier-1444 - Streaming: events -> 776
2020-04-12 16:02:07,956 - synapse.replication.http.send_event - 119 - INFO - POST-1178 - Got event to send with ID: $F_t8Jzte71HEfYW-bBM4pLqG26bNivEyJEt_1HV4k9E into room: !UJfEiVhWyjgjLYLDjv:localhost:8831
2020-04-12 16:02:07,987 - synapse.access.http.8801 - 301 - INFO - POST-1178 - 127.0.0.1 - 8801 - {@7:localhost:8831} Processed request: 0.031sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.001sec/1) 2B 200 "POST /_synapse/replication/send_event/%24F_t8Jzte71HEfYW-bBM4pLqG26bNivEyJEt_1HV4k9E/oOLVSKmtSl HTTP/1.1" "Synapse/1.12.3 homeserver[0]" [0 dbevts]
2020-04-12 16:02:07,992 - synapse.replication.http.membership - 193 - INFO - POST-1179 - user membership change: @7:localhost:8831 in !UJfEiVhWyjgjLYLDjv:localhost:8831

Of course our methods for grabbing the latest state from a room are cached:

https://github.com/matrix-org/synapse/blob/4a17a647a9508b70de35130fd82e3e21474270a9/synapse/storage/data_stores/main/event_federation.py#L386-L393

Could it be that we're not invalidating this cache on membership change?

The method that's run after the user_membership_change log line doesn't inspire much confidence:

https://github.com/matrix-org/synapse/blob/118b58f0c9897243f98072755cbc6606528dfa6c/synapse/util/distributor.py#L30-L32

'Guest user can set display names' is flaky #836

Description

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions