Synapse: Purge job don't see messages older than configured retention period in room

[MurzNN]

I have room with configured m.room.retention state, last state event is:

{
    "type": "m.room.retention",
    "sender": "@korepov:myhomeserver.org",
    "content": {
        "max_lifetime": 8650000
    },
    "event_id": "$EzvTrUpYO0PM4EgMVR991UHt3jLYG3l51wJ2CvbZ6iw",
    "origin_server_ts": 1579706653940,
    "unsigned": {
        "replaces_state": "$k5bCedn5D_RNrFHKOLmKCh2IUGBqrETrj3Fgnxt0_1s",
        "prev_content": {
            "max_lifetime": 3600000
        },
        "prev_sender": "@korepov:myhomeserver.org",
        "age": 78
    },
    "room_id": "!FvoraUJnHgFXgVlygJ:myhomeserver.org"
}

Here is my config records:

retention:
  enabled: true

  allowed_lifetime_min: 1h
  allowed_lifetime_max: 1y

  purge_jobs:
    - shortest_max_lifetime: 1h
      longest_max_lifetime: 3d
      interval: 5m
    - shortest_max_lifetime: 3d
      longest_max_lifetime: 1y
      interval: 24h

And here is purge job logs - first purge job log:

2020-01-23 17:00:10,031 - synapse.handlers.pagination - 139 - INFO - purge_history_for_rooms_in_range-0 - [purge] Running purge job for 3600000 < max_lifetime <= 259200000 (include NULLs = False)
2020-01-23 17:00:10,033 - synapse.handlers.pagination - 149 - INFO - purge_history_for_rooms_in_range-0 - [purge] Attempting to purge messages in room !FvoraUJnHgFXgVlygJ:myhomeserver.org
2020-01-23 17:00:10,036 - synapse.handlers.pagination - 192 - INFO - purge_history_for_rooms_in_range-0 - Starting purging events in room !FvoraUJnHgFXgVlygJ:myhomeserver.org (purge_id EdawZfUpifvzftxt)
2020-01-23 17:00:10,037 - synapse.handlers.pagination - 149 - INFO - purge_history_for_rooms_in_range-0 - [purge] Attempting to purge messages in room !hUaPUOxDijRCIPbYMN:myhomeserver.org
2020-01-23 17:00:10,037 - synapse.storage.data_stores.main.events - 1498 - INFO - _purge_history-0 - [purge] looking for events to delete
2020-01-23 17:00:10,072 - synapse.storage.data_stores.main.events - 1539 - INFO - _purge_history-0 - [purge] found 2 events before cutoff, of which 1 can be deleted
2020-01-23 17:00:10,075 - synapse.storage.data_stores.main.events - 1542 - INFO - _purge_history-0 - [purge] Finding new backward extremities
2020-01-23 17:00:10,079 - synapse.storage.data_stores.main.events - 1555 - INFO - _purge_history-0 - [purge] replacing backward extremities: [('$EzvTrUpYO0PM4EgMVR991UHt3jLYG3l51wJ2CvbZ6iw',)]
2020-01-23 17:00:10,093 - synapse.storage.data_stores.main.events - 1568 - INFO - _purge_history-0 - [purge] finding state groups referenced by deleted events
2020-01-23 17:00:10,111 - synapse.storage.data_stores.main.events - 1581 - INFO - _purge_history-0 - [purge] found 2 referenced state groups
2020-01-23 17:00:10,111 - synapse.storage.data_stores.main.events - 1584 - INFO - _purge_history-0 - [purge] removing events from event_to_state_groups
2020-01-23 17:00:10,115 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from events
2020-01-23 17:00:10,116 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from event_json
2020-01-23 17:00:10,117 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from event_auth
2020-01-23 17:00:10,123 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from event_edges
2020-01-23 17:00:10,127 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from event_forward_extremities
2020-01-23 17:00:10,128 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from event_reference_hashes
2020-01-23 17:00:10,134 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from event_search
2020-01-23 17:00:10,162 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-0 - [purge] removing events from rejections
2020-01-23 17:00:10,162 - synapse.storage.data_stores.main.events - 1614 - INFO - _purge_history-0 - [purge] removing events from event_push_actions
2020-01-23 17:00:10,163 - synapse.storage.data_stores.main.events - 1624 - INFO - _purge_history-0 - [purge] marking remaining events as outliers
2020-01-23 17:00:10,163 - synapse.storage.data_stores.main.events - 1657 - INFO - _purge_history-0 - [purge] updating room_depth to 35
2020-01-23 17:00:10,163 - synapse.storage.data_stores.main.events - 1668 - INFO - _purge_history-0 - [purge] done
2020-01-23 17:00:10,203 - synapse.storage.purge_events - 57 - INFO - _purge_history-0 - [purge] finding state groups that can be deleted
2020-01-23 17:00:10,225 - synapse.handlers.pagination - 180 - WARNING - purge_history_for_rooms_in_range-0 - [purge] purging events not possible: No event found (ts 1579701610038 => stream_ordering 647)

And second job find nothing:

Running purge job for 3600000 < max_lifetime <= 259200000 (include NULLs = False)
2020-01-23 17:05:10,034 - synapse.handlers.pagination - 149 - INFO - purge_history_for_rooms_in_range-1 - [purge] Attempting to purge messages in room !FvoraUJnHgFXgVlygJ:myhomeserver.org
2020-01-23 17:05:10,037 - synapse.handlers.pagination - 192 - INFO - purge_history_for_rooms_in_range-1 - Starting purging events in room !FvoraUJnHgFXgVlygJ:myhomeserver.org (purge_id CUkWIEQgJhhCBsFW)
2020-01-23 17:05:10,038 - synapse.handlers.pagination - 149 - INFO - purge_history_for_rooms_in_range-1 - [purge] Attempting to purge messages in room !hUaPUOxDijRCIPbYMN:myhomeserver.org
2020-01-23 17:05:10,039 - synapse.storage.data_stores.main.events - 1498 - INFO - _purge_history-2 - [purge] looking for events to delete
2020-01-23 17:05:10,042 - synapse.storage.data_stores.main.events - 1539 - INFO - _purge_history-2 - [purge] found 0 events before cutoff, of which 0 can be deleted
2020-01-23 17:05:10,043 - synapse.storage.data_stores.main.events - 1542 - INFO - _purge_history-2 - [purge] Finding new backward extremities
2020-01-23 17:05:10,044 - synapse.storage.data_stores.main.events - 1555 - INFO - _purge_history-2 - [purge] replacing backward extremities: []
2020-01-23 17:05:10,045 - synapse.storage.data_stores.main.events - 1568 - INFO - _purge_history-2 - [purge] finding state groups referenced by deleted events
2020-01-23 17:05:10,046 - synapse.storage.data_stores.main.events - 1581 - INFO - _purge_history-2 - [purge] found 0 referenced state groups
2020-01-23 17:05:10,047 - synapse.storage.data_stores.main.events - 1584 - INFO - _purge_history-2 - [purge] removing events from event_to_state_groups
2020-01-23 17:05:10,047 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from events
2020-01-23 17:05:10,048 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from event_json
2020-01-23 17:05:10,049 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from event_auth
2020-01-23 17:05:10,049 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from event_edges
2020-01-23 17:05:10,049 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from event_forward_extremities
2020-01-23 17:05:10,050 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from event_reference_hashes
2020-01-23 17:05:10,050 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from event_search
2020-01-23 17:05:10,052 - synapse.storage.data_stores.main.events - 1603 - INFO - _purge_history-2 - [purge] removing events from rejections
2020-01-23 17:05:10,053 - synapse.storage.data_stores.main.events - 1614 - INFO - _purge_history-2 - [purge] removing events from event_push_actions
2020-01-23 17:05:10,053 - synapse.storage.data_stores.main.events - 1624 - INFO - _purge_history-2 - [purge] marking remaining events as outliers
2020-01-23 17:05:10,054 - synapse.storage.data_stores.main.events - 1657 - INFO - _purge_history-2 - [purge] updating room_depth to 0
2020-01-23 17:05:10,055 - synapse.storage.data_stores.main.events - 1668 - INFO - _purge_history-2 - [purge] done
2020-01-23 17:05:10,072 - synapse.storage.purge_events - 57 - INFO - _purge_history-2 - [purge] finding state groups that can be deleted
2020-01-23 17:05:10,083 - synapse.storage.data_stores.state.store - 511 - INFO - _purge_history-2 - [purge] found 0 state groups to delete
2020-01-23 17:05:10,084 - synapse.storage.data_stores.state.store - 531 - INFO - _purge_history-2 - [purge] de-delta-ing 0 remaining state groups
2020-01-23 17:05:10,085 - synapse.storage.data_stores.state.store - 564 - INFO - _purge_history-2 - [purge] removing redundant state groups
2020-01-23 17:05:10,086 - synapse.handlers.pagination - 252 - INFO - _purge_history-2 - [purge] complete

And room still have many messages, older than setted up period. Where can be the problem?

[MurzNN]

Seems deleting works well on Synapse side, the problem is in Riot (and RiotX) local cache. After I force clear cache - those messages are disappear from room timeline.

[richvdh]

sounds like this is working correctly from the synapse side. remember that retention periods are experimental for this sort of reason.

[MurzNN]

Yes, the source of problem is that Matrix spec don't have methods to inform clients about retention events in room. Is this planned already, or need separate MSC?

[yousefalatari]

Hi @MurzNN , can u please tell me how did configure the room with m.room.retention event ?
are u using Riot Android ?

[MurzNN]

@yousefalatari I use Riot-web /devtools for set state m.room.retention event. Messages are correctly removed from Synapse database, but still available on RiotX-android and Riot-web, and disappear only when I clear cache manually.

After clearing cache in Riot-web, when room have no "fresh" messages (becomes empty after cleaning), there are also other problem, that room always stay as "bold", seems because read marker points to already deleted event, that Riot can't receive from server.

[yousefalatari]

@MurzNN , Thanks for your assistance , that is what i was thinking to do :)
But i see also that we can avoid sending "m.room.retention" by using using default policy configurations on Synpase and setting the config as below ;

default_policy:

# min_lifetime: 1d
# max_lifetime: 1y
I think this will be applied for all rooms that did not send "m.room.retention".
@babolivier , @richvdh , @MurzNN can you please confirm this point ?

[babolivier]

That is true, but it will only apply to your server, and not propagate to other servers.

The main point of storing the retention policy in a state event is so that every participating server in the room that supports this feature (e.g. have the enabled flag set to true for Synapse) can know about the room's policy and apply it.

[MurzNN]

That is true, but it will only apply to your server, and not propagate to other servers.

Matrix rooms can have private "per homeserver" state events, that not shared to other servers? o_O

[babolivier]

Matrix rooms can have private "per homeserver" state events, that not shared to other servers? o_O

No. As @yousefalatari said, configuring the default_policy section of the config doesn't send any state event.