Old messages reappear (after using purge history API?)

[aaronraimist]

Description

I often get bursts of 10-15 messages I've seen before that are weeks or months old. This happens seemingly at random, every day, and has been happening for a long time now. My theory is that maybe happens because I sometimes use the purge history API and
then other servers think "hey you missed these messages, let me helpfully send them to you".

One example from today in #matrix:matrix.org:

Logs from that time grep "federation" | grep "beerfactory.org", let me know if you need more

May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,505 - synapse.federation.transport.server - 139 - INFO - PUT-23299 - Request from beerfactory.org
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,508 - synapse.federation.transport.server - 340 - DEBUG - PUT-23299 - Decoded 1558556868478: {'origin': 'beerfactory.org', 'origin_server_ts': 1558627152111, 'pdus': [{'auth_events': [['$155613797223UAbOk:sw1v.org', {'sha256': '571hpra6Oo8ezVI67h8dWrnArQibHZaEmhmr8Vxi/3Q'}], ['$152873010877837iaEeS:matrix.org', {'sha256': 'FadaICEbPU11CFeC8NlvANHQdkviLqR7R3dgLQ7tElE'}], ['$15362583271SLSmP:beerfactory.org', {'sha256': '6s9iG8+wFRdeb9JJ4QpHWwozHWOfu4HiJtIAz42o/b0'}]], 'content': {'body': 'https://matrix.org/ website seems available again.', 'msgtype': 'm.text'}, 'depth': 133921, 'event_id': '$1558627148122HiTWz:beerfactory.org', 'hashes': {'sha256': 'c/7wfFajIf0T3ieP79EKyM5nHovb11IXeGq4/nj5swQ'}, 'origin': 'beerfactory.org', 'origin_server_ts': 1558627148874, 'prev_events': [['$15513813901LTdYv:earfolds.com', {'sha256': 'XgJqbsnVuVaV7L9QCEabzRqxfh9JtFXlzeeY5JxknQI'}], ['$15507611943142fAEMU:swedneck.xyz', {'sha256': 'qkXXBJZ56AeD4NzkQwj8HtyYPI884+qNSsD9BDwTa4k'}], ['$155075324348751lGcDi:matrix.org', {'sha256': 'hqw56I1s9rN3Ue5C/oEBQSwNgpDC/0DcAHySS/bp33Y'}], ['$15507064431726QtAiL:maunium.net', {'sha256': 'LNoRB24lQ5jJ+rE+0/n7wMANI+C/YpKcBp77IZ7nFzM'}], ['$15504926471504oxHcE:chat.weho.st', {'sha256': 'alZXhWfuuFN49PiX1aFSgYd+QjqWwrdyem+3R6zU95o'}], ['$15506821851364fwJlu:maunium.net', {'sha256': 'IsejczHOy1ZHHfMS71zBe7NpHIn43SLwDQZWni+QE2Q'}], ['$1550518491845dBASB:disroot.org', {'sha256': 'HenIxoMKm/tm1jDScsQK8GxYQJ9KUtm2zH2yJL1TdJQ'}], ['$155862697872894KgAeW:t2bot.io', {'sha256': 'DYII2UCwLrgPasXGbLtpSYPbXpFcsSAtUTBp1h9vpSI'}], ['$15586269907283pOOBZ:matrix.org', {'sha256': '4nSaBCGiqFV4b91bXv6Hsuz+oEsiczWsJFTvPdidmeI'}], ['$1558627095332oEfWa:foad.me.uk', {'sha256': 'MFFABsi6Y0nRqSe59ITWMQAbGEyIjRhnp2Q5M6JmNQ0'}]], 'prev_state': [], 'room_id': '!QtykxKocfZaZOUrTwp:matrix.org', 'sender': '@nico:beerfactory.org', 'signatures': {'beerfactory.org': {'ed25519:a_TwNd': 'PVktKtfmnuBwPJnmRI5IIvq2fhfRsrC6VCksAQkTOp38NiKUrxlcib4KlfBBqgQ3JI8Nt2PvQe6dxcHxU2RWCQ'}}, 'type': 'm.room.message', 'unsigned': {'age_ts': 1558627148874}}]}
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,508 - synapse.federation.transport.server - 347 - INFO - PUT-23299 - Received txn 1558556868478 from beerfactory.org. (PDUs: 1, EDUs: 0)
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,519 - synapse.federation.federation_server - 105 - DEBUG - PUT-23299 - Invoked 'on_incoming_transaction' with args: self=<ReplicationLayer(raim.ist)>, origin=beerfactory.org, transaction_data={'origin': 'beerfactory.org', 'origin_server_ts': ...
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,520 - synapse.federation.persistence - 38 - DEBUG - PUT-23299 - Invoked 'have_responded' with args: self=<synapse.federation.persistence.TransactionActions..., origin=beerfactory.org, transaction=(Transaction, {'unrecognized_keys': {}, 'transacti...
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,524 - synapse.federation.federation_server - 764 - DEBUG - PUT-23299 - Checking beerfactory.org against acl {'allow': ['*'], 'allow_ip_literals': False, 'deny': ['zemos.net', 'gossip.love', 'c-24-11-108-182.hsd1.ut.comcast.net', 'ardaxi.com', 'ordoevangelistarum.com', '*.ordoevangelistarum.com']}
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,528 - synapse.handlers.federation - 151 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org] handling received PDU: <FrozenEvent event_id='$1558627148122HiTWz:beerfactory.org', type='m.room.message', state_key='None'>
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,536 - synapse.handlers.federation - 227 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org] min_depth: 47244
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,558 - synapse.handlers.federation - 246 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org] Acquiring room lock to fetch 6 missing prev_events: ['$15506821851364fwJlu:maunium.net', '$15507064431726QtAiL:maunium.net', '$15504926471504oxHcE:chat.weho.st', '$1550518491845dBASB:disroot.org', '$15507611943142fAEMU:swedneck.xyz', ...]
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,559 - synapse.handlers.federation - 251 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org] Acquired room lock to fetch 6 missing prev_events
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,565 - synapse.handlers.federation - 445 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org]: Requesting missing events between ['$15586269907283pOOBZ:matrix.org', '$155075324348751lGcDi:matrix.org', '$1558627095332oEfWa:foad.me.uk', '$155059223814077zyFUo:maunium.net', '$1550276402291iSfdV:tawk.club', ...] and $1558627148122HiTWz:beerfactory.org
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,565 - synapse.federation.transport.client - 489 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org - Invoked 'get_missing_events' with args: self=<synapse.federation.transport.client.TransportLaye..., destination=beerfactory.org, room_id=!QtykxKocfZaZOUrTwp:matrix.org, earliest_events=['$15586269907283pOOBZ:matrix.org', '$155075324348..., latest_events=['$1558627148122HiTWz:beerfactory.org'], limit=10, min_depth=47244, timeout=60000
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,566 - synapse.http.matrixfederationclient - 384 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - {POST-O-936} [beerfactory.org] Sending request: POST matrix://beerfactory.org/_matrix/federation/v1/get_missing_events/%21QtykxKocfZaZOUrTwp%3Amatrix.org; timeout 60.000000s
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,567 - synapse.http.federation.matrix_federation_agent - 273 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org - Picked matrix.beerfactory.org:8448 from SRV records for beerfactory.org
May 23 15:59:12 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:12,568 - synapse.http.federation.matrix_federation_agent - 373 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - Connecting to matrix.beerfactory.org:8448
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,732 - synapse.http.matrixfederationclient - 416 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - {POST-O-936} [beerfactory.org] Got response headers: 200 OK
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,733 - synapse.http.matrixfederationclient - 160 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - {POST-O-936} [beerfactory.org] Completed: 200 OK
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,746 - synapse.handlers.federation - 508 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org]: Got 10 prev_events: [<FrozenEvent event_id='$15513813800mNLbn:earfolds.com', type='m.room.message', state_key='None'>, <FrozenEvent event_id='$1550706413442760rPcjp:matrix.org', type='m.room.message', state_key='None'>, <FrozenEvent event_id='$155070642729229XPkxk:dodsorf.as', type='m.room.message', state_key='None'>, <FrozenEvent event_id='$15507611333141RsnLQ:swedneck.xyz', type='m.room.message', state_key='None'>, <FrozenEvent event_id='$1550518491845dBASB:disroot.org', type='m.room.message', state_key='None'>, ...]
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,747 - synapse.handlers.federation - 518 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org - [!QtykxKocfZaZOUrTwp:matrix.org $1558627148122HiTWz:beerfactory.org] Handling received prev_event $15504926471504oxHcE:chat.weho.st
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,747 - synapse.handlers.federation - 151 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st - [!QtykxKocfZaZOUrTwp:matrix.org $15504926471504oxHcE:chat.weho.st] handling received PDU: <FrozenEvent event_id='$15504926471504oxHcE:chat.weho.st', type='m.room.message', state_key='None'>
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,753 - synapse.handlers.federation - 227 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st - [!QtykxKocfZaZOUrTwp:matrix.org $15504926471504oxHcE:chat.weho.st] min_depth: 47244
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,757 - synapse.handlers.federation - 270 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st - [!QtykxKocfZaZOUrTwp:matrix.org $15504926471504oxHcE:chat.weho.st] Not recursively fetching 1 missing prev_events: ['$15504926221496RtJGz:chat.weho.st']
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,757 - synapse.handlers.federation - 335 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st - [!QtykxKocfZaZOUrTwp:matrix.org $15504926471504oxHcE:chat.weho.st] Requesting state at missing prev_event $15504926221496RtJGz:chat.weho.st
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,758 - synapse.federation.federation_client - 303 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - Invoked 'get_state_for_room' with args: self=<synapse.federation.federation_client.FederationCl..., destination=beerfactory.org, room_id=!QtykxKocfZaZOUrTwp:matrix.org, event_id=$15504926221496RtJGz:chat.weho.st
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,758 - synapse.federation.transport.client - 60 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - Invoked 'get_room_state_ids' with args: self=<synapse.federation.transport.client.TransportLaye..., destination=beerfactory.org, room_id=!QtykxKocfZaZOUrTwp:matrix.org, event_id=$15504926221496RtJGz:chat.weho.st
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,758 - synapse.federation.transport.client - 75 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - get_room_state_ids dest=beerfactory.org, room=!QtykxKocfZaZOUrTwp:matrix.org
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,758 - synapse.http.matrixfederationclient - 714 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - get_json args: {'event_id': '$15504926221496RtJGz:chat.weho.st'}
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,759 - synapse.http.matrixfederationclient - 716 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - Query bytes: {'event_id': '$15504926221496RtJGz:chat.weho.st'} Retry DNS: True
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,759 - synapse.http.matrixfederationclient - 384 - INFO - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - {GET-O-937} [beerfactory.org] Sending request: GET matrix://beerfactory.org/_matrix/federation/v1/state_ids/%21QtykxKocfZaZOUrTwp%3Amatrix.org?event_id=%2415504926221496RtJGz%3Achat.weho.st; timeout 60.000000s
May 23 15:59:13 ubuntu matrix-synapse[14804]: 2019-05-23 15:59:13,760 - synapse.http.federation.matrix_federation_agent - 273 - DEBUG - PUT-23299-$1558627148122HiTWz:beerfactory.org-$15504926471504oxHcE:chat.weho.st-$15504926221496RtJGz:chat.weho.st - Picked matrix.beerfactory.org:8448 from SRV records for beerfactory.org

The event IDs in here correspond to the old messages in the screenshot .

Version information

• Homeserver: raim.ist

If not matrix.org:

• Version: 0.99.5rc1
• Install method: Docker (matrix-docker-ansible-deploy)
• Platform: Ubuntu 18.04

[neilisfragile]

It could be related to the remote server having old DAG extremities that they are sending to you. Then your server gets mixed up due to the purge.
I asked for comments here https://matrix.to/#/!yZHTGeDKZUeKaqeTeU:matrix.org/$1558715933117115hGQGE:matrix.org?via=matrix.org&via=sw1v.org&via=t2l.io

[aaronraimist]

Another data point: @jonah:privacytools.io and I both got this in #matrix:matrix.org just now and he has not used the purge history API on the room. Maybe these were real events that we both were never sent but it looks like a very similar pattern of events from mid February

[richvdh]

I think this is expected behaviour: your server will pull in old events that it has not previously seen (or that you have purged) if they are referenced as prev_events from new events.

[richvdh]

I think this is expected behaviour:

on which basis, I'm going to close this.