Stopping typing notifications seems to be broken since 1.62.0 for initial syncs

[deepbluev7]

Description

If you stop typing notifications using the explicit typing API, it seems that the last typing event always comes down /sync if you provide no since token. This works fine with 1.61.0, but is broken with 1.62.0 up to 1.61.1 (latest as of writing). I think it is the same issue as the stuck notification issue in 1.62.0.

Steps to reproduce

Run a local synapse server with the registered user @alice:localhost and the password "secret".

Then run this script:

#!/bin/bash

access_token=$(curl -s -k -X POST -d '{ "user": "alice", "password": "secret", "type": "m.login.password" }' https://localhost/_matrix/client/v3/login | jq -r .access_token)

roomid=$(curl -s -k -H "Authorization: Bearer $access_token" -X POST -d '{}' https://localhost/_matrix/client/v3/createRoom | jq -r .room_id)

echo $roomid

curl -s -k -H "Authorization: Bearer $access_token" -X PUT -d '{ "typing": true, "timeout": 10000 }' "https://localhost/_matrix/client/v3/rooms/${roomid}/typing/@alice:localhost"
curl -s -k -H "Authorization: Bearer $access_token" "https://localhost/_matrix/client/v3/sync?timeout=0" | jq .rooms.join[\"$roomid\"].ephemeral.events
curl -s -k -H "Authorization: Bearer $access_token" -X PUT -d '{ "typing": false }' "https://localhost/_matrix/client/v3/rooms/${roomid}/typing/@alice:localhost"
curl -s -k -H "Authorization: Bearer $access_token" "https://localhost/_matrix/client/v3/sync?timeout=0" | jq .rooms.join[\"$roomid\"].ephemeral.events

On 1.61.0 and below, the second sync will have no typing users, on 1.62.0 and up it always has alice as typing no matter how long you sleep.

Homeserver

mtxclient CI

Synapse Version

1.62.0-1.63.1

Installation Method

Docker (matrixdotorg/synapse)

Platform

Docker container in CI and locally on linux dev systems

Relevant log output

2022-07-24 12:58:23,232 - synapse.handlers.auth - 965 - INFO - POST-7 - Logging in user @alice:localhost on device JQQNBWUDTL
2022-07-24 12:58:23,247 - synapse.access.https.8008 - 450 - INFO - POST-7 - ::ffff:172.17.0.1 - 8008 - {None} Processed request: 0.774sec/0.002sec (0.733sec, 0.011sec) (0.004sec/0.022sec/5) 138B 200 "POST /_matrix/client/v3/login HTTP/1.1" "curl/7.84.0" [0 dbevts]
2022-07-24 12:58:24,056 - synapse.access.https.8008 - 450 - INFO - POST-8 - ::ffff:172.17.0.1 - 8008 - {@alice:localhost} Processed request: 0.752sec/0.003sec (0.192sec, 0.020sec) (0.231sec/0.123sec/46) 43B 200 "POST /_matrix/client/v3/createRoom HTTP/1.1" "curl/7.84.0" [0 dbevts]
2022-07-24 12:58:24,164 - synapse.access.https.8008 - 450 - INFO - PUT-9 - ::ffff:172.17.0.1 - 8008 - {@alice:localhost} Processed request: 0.040sec/0.003sec (0.012sec, 0.000sec) (0.012sec/0.012sec/4) 2B 200 "PUT /_matrix/client/v3/rooms/!oDCBzvNOmdNwVQHBqW:localhost/typing/@alice:localhost HTTP/1.1" "curl/7.84.0" [0 dbevts]
2022-07-24 12:58:24,300 - synapse.access.https.8008 - 450 - INFO - GET-10 - ::ffff:172.17.0.1 - 8008 - {@alice:localhost} Processed request: 0.080sec/0.003sec (0.045sec, 0.006sec) (0.012sec/0.016sec/15) 5988B 200 "GET /_matrix/client/v3/sync?timeout=0 HTTP/1.1" "curl/7.84.0" [0 dbevts]
2022-07-24 12:58:24,363 - synapse.access.https.8008 - 450 - INFO - PUT-11 - ::ffff:172.17.0.1 - 8008 - {@alice:localhost} Processed request: 0.007sec/0.003sec (0.005sec, 0.000sec) (0.001sec/0.001sec/1) 2B 200 "PUT /_matrix/client/v3/rooms/!oDCBzvNOmdNwVQHBqW:localhost/typing/@alice:localhost HTTP/1.1" "curl/7.84.0" [0 dbevts]
2022-07-24 12:58:42,924 - synapse.storage.databases.main.event_push_actions - 833 - INFO - rotate_notifs-3 - Rotating notifications
2022-07-24 12:58:42,925 - synapse.storage.databases.main.event_push_actions - 986 - INFO - rotate_notifs-3 - Rotating notifications up to: 7
2022-07-24 12:58:42,926 - synapse.storage.databases.main.event_push_actions - 1060 - INFO - rotate_notifs-3 - Rotating notifications, handling 0 rows
2022-07-24 12:58:42,938 - synapse.storage.databases.main.event_push_actions - 1162 - INFO - rotate_notifs-3 - Rotating notifications, deleted 0 push actions
2022-07-24 12:58:42,979 - synapse.handlers.presence - 792 - INFO - persist_presence_changes-0 - Persisting 1 unpersisted presence updates
2022-07-24 12:58:43,007 - synapse.util.caches.lrucache - 206 - INFO - LruCache._expire_old_entries-3 - Dropped 0 items from caches
2022-07-24 12:59:12,923 - synapse.storage.databases.main.event_push_actions - 833 - INFO - rotate_notifs-4 - Rotating notifications
2022-07-24 12:59:12,924 - synapse.storage.databases.main.event_push_actions - 986 - INFO - rotate_notifs-4 - Rotating notifications up to: 7
2022-07-24 12:59:12,925 - synapse.storage.databases.main.event_push_actions - 1060 - INFO - rotate_notifs-4 - Rotating notifications, handling 0 rows
2022-07-24 12:59:12,928 - synapse.storage.databases.main.event_push_actions - 1162 - INFO - rotate_notifs-4 - Rotating notifications, deleted 0 push actions
2022-07-24 12:59:13,007 - synapse.util.caches.lrucache - 206 - INFO - LruCache._expire_old_entries-4 - Dropped 0 items from caches
2022-07-24 12:59:24,435 - synapse.util.caches.response_cache - 254 - INFO - GET-12 - [sync]: using completed cached result for [(@alice:localhost, 0, None, None, False, 'JQQNBWUDTL')]
2022-07-24 12:59:24,439 - synapse.access.https.8008 - 450 - INFO - GET-12 - ::ffff:172.17.0.1 - 8008 - {@alice:localhost} Processed request: 0.017sec/0.002sec (0.009sec, 0.000sec) (0.001sec/0.007sec/1) 6003B 200 "GET /_matrix/client/v3/sync?timeout=0 HTTP/1.1" "curl/7.84.0" [0 dbevts]

Anything else that would be useful to know?

No response

[DMRobertson]

In both cases you are requesting an initial sync.

curl -s -k -H "Authorization: Bearer $access_token" "https://localhost/_matrix/client/v3/sync?timeout=0" | jq .rooms.join[\"$roomid\"].ephemeral.events

Sync responses are cached for performance's sake. If you follow-up with incremental syncs, do you see that alice is no longer typing?

[deepbluev7]

That does indeed fix it, seems like I missed #13042 . I guess this is easy enough to workaround in my test cases and I can worst case just disable the caching. Sorry for the noise!

This test case was intentionally not doing an incremental sync originally, but I guess I can't rely on an initialSync to give me the current full state anymore for understandable reasons.