Sender profile is correct in scrollback but not in /sync (LL disabled)

[ara4n]

I joined #seaglass:matrix.org from @matthew:sandbox.modular.im. The scrollback for the room shows @neil:sandbox.modular.im with the correct avatar & displayname (Neil). But the messages added to the timeline subsequently have the wrong profile (no avatar, and displayname of neil).

[ara4n]

@bwindels do you think there's a risk this is a regression introduced by LL stuff?

[bwindels]

hard to tell, but that is what it looks like, yeah. Do you remember if there might have been a gappy sync in between?

[ara4n]

no gappy sync; this was on joining the room for the first time.

interesting logs from before i lost the browser tab:

for (e in r.timeline) { ev = r.timeline[e]; console.log(ev.sender.userId, ev.getId(), ev.sender.events.member.getId(), ev.getType(), ev.sender.name ); }
rageshake.js:66 @neil:sandbox.modular.im $153684595621VtKMq:sandbox.modular.im $153684597222hUyJL:sandbox.modular.im m.room.member neil
rageshake.js:66 @neil:sandbox.modular.im $153684597222hUyJL:sandbox.modular.im $153684598024VquWQ:sandbox.modular.im m.room.member Neil
rageshake.js:66 @neil:sandbox.modular.im $153684598024VquWQ:sandbox.modular.im $153684598024VquWQ:sandbox.modular.im m.room.member Neil
rageshake.js:66 @neilalexander:matrix.org $1536846005270254dDbqw:matrix.org $152853865421691urKOW:matrix.org m.room.power_levels neilalexander
rageshake.js:66 @matthew:matrix.org $1536846085270586XnDKX:matrix.org $15285388271157470bLGbb:matrix.org m.room.message Matthew
rageshake.js:66 @matthew:matrix.org $1536846093270619zdkvQ:matrix.org $15285388271157470bLGbb:matrix.org m.room.message Matthew
rageshake.js:66 @neil:sandbox.modular.im $153684612530zhrKf:sandbox.modular.im $153684598024VquWQ:sandbox.modular.im m.room.message Neil
rageshake.js:66 @neil:sandbox.modular.im $153684613831iNjCw:sandbox.modular.im $153684598024VquWQ:sandbox.modular.im m.room.message Neil
rageshake.js:66 @matthew:sandbox.modular.im $153684625244iItIq:sandbox.modular.im $153684625244iItIq:sandbox.modular.im m.room.member matthew
rageshake.js:66 @matthew:sandbox.modular.im $153684625747spuff:sandbox.modular.im $153684625244iItIq:sandbox.modular.im m.room.message matthew
rageshake.js:66 @matthew:sandbox.modular.im $153684627548qnAoz:sandbox.modular.im $153684627548qnAoz:sandbox.modular.im m.room.member Matthew
rageshake.js:66 @matthew:matrix.org $1536846439272040pHxsz:matrix.org $15285388271157470bLGbb:matrix.org m.room.message Matthew
rageshake.js:66 @matthew:matrix.org $1536846447272068vOYTn:matrix.org $15285388271157470bLGbb:matrix.org m.room.message Matthew
rageshake.js:66 @matthew:matrix.org $1536846451272087EQXdG:matrix.org $15285388271157470bLGbb:matrix.org m.room.message Matthew
rageshake.js:66 @matthew:matrix.org $1536846470272180QaEWW:matrix.org $15285388271157470bLGbb:matrix.org m.room.message Matthew
rageshake.js:66 @aaron:raim.ist $153684648493tJkAT:raim.ist $152865483815ShXSn:raim.ist m.room.message Aaron Raimist
rageshake.js:66 @_neb_github_=40neilalexander=3amatrix.org:matrix.org $1536846569272568qfHoY:matrix.org $1529249318188991QkSSZ:matrix.org m.room.message Github [@neilalexander:matrix.org]
rageshake.js:66 @aaron:raim.ist $153684659494xmWFp:raim.ist $152865483815ShXSn:raim.ist m.room.message Aaron Raimist
rageshake.js:66 @neil:sandbox.modular.im $153684661554HEiUy:sandbox.modular.im $153684595621VtKMq:sandbox.modular.im m.room.message neil
rageshake.js:66 @neil:sandbox.modular.im $153684663155RpsAM:sandbox.modular.im $153684595621VtKMq:sandbox.modular.im m.room.message neil


JSON.stringify(r.getMember('@neil:sandbox.modular.im'))
{
  "roomId": "!qvCRFpZsGETXtHJSnJ:matrix.org",
  "userId": "@neil:sandbox.modular.im",
  "typing": false,
  "name": "neil",
  "rawDisplayName": "neil",
  "powerLevel": 0,
  "powerLevelNorm": 0,
  "user": {
    "userId": "@neil:sandbox.modular.im",
    "presence": "online",
    "presenceStatusMsg": null,
    "displayName": "neil",
    "rawDisplayName": "neil",
    "avatarUrl": "mxc://sandbox.modular.im/zSGcibfVekqoAMVfubDarVgm",
    "lastActiveAgo": 24633,
    "lastPresenceTs": 1536917607065,
    "currentlyActive": true,
    "events": {
      "presence": {
        "event": {
          "content": {
            "currently_active": true,
            "last_active_ago": 24633,
            "presence": "online"
          },
          "type": "m.presence",
          "sender": "@neil:sandbox.modular.im"
        },
        "sender": null,
        "target": null,
        "status": null,
        "error": null,
        "forwardLooking": true,
        "_pushActions": {},
        "_clearEvent": {},
        "_senderCurve25519Key": null,
        "_claimedEd25519Key": null,
        "_forwardingCurve25519KeyChain": [],
        "_decryptionPromise": null,
        "_retryDecryption": false
      },
      "profile": null
    },
    "_modified": 1536917607065,
    "_events": {}
  },
  "membership": "join",
  "events": {
    "member": {
      "event": {
        "origin_server_ts": 1536845951613,
        "sender": "@neil:sandbox.modular.im",
        "event_id": "$153684595621VtKMq:sandbox.modular.im",
        "unsigned": {
          "age": 301516
        },
        "state_key": "@neil:sandbox.modular.im",
        "content": {
          "membership": "join",
          "avatar_url": null,
          "displayname": "neil"
        },
        "type": "m.room.member",
        "room_id": "!qvCRFpZsGETXtHJSnJ:matrix.org"
      },
      "sender": null,
      "target": null,
      "status": null,
      "error": null,
      "forwardLooking": true,
      "_pushActions": {
        "notify": false,
        "tweaks": {
          "highlight": false
        }
      },
      "_clearEvent": {},
      "_senderCurve25519Key": null,
      "_claimedEd25519Key": null,
      "_forwardingCurve25519KeyChain": [],
      "_decryptionPromise": null,
      "_retryDecryption": false
    }
  },
  "_isOutOfBand": false,
  "_supersedesOutOfBand": false,
  "_modified": 1536917064428,
  "_events": {}
}

and (in terms of #7335), there were no sentinels at all in the room.oldState (aka liveTimeline.startState). There was also no paginationToken at all in oldState, hence #7335.

[ara4n]

We tried to repro this earlier but failed, but i think the key missing ingredient is that the room has to start off federated. This means that when the first local user joins, there isn't any DAG available to sync, so their join will have no history at all. When the second local user joins, they may only see the local room history if the remote stuff hasn't arrived yet - and if the second user doesn't even see the local room history, then it might only arrive via /messages, then that might explain why we have correct members in the history loaded by /messages, but not in the ongoing forward-paginating timeline.

[ara4n]

Fwiw, this feels like a sentinel bug to me:that riot propagates the sentinels correctly when going backwards in time, but incorrectly when going forwards, for reasons unknown.

Next step is to reproduce it with a federated room and see where the incorrect state sneaks in.

[ara4n]

To try to spell out the scenarii i'm guessing at here:

1. A.com has a room with timeline e1, e2, e3, e4, e5, all sent by Alice, where e1 is her membership event.
2. user X on B.com joins A.com, and during join B.com gets a copy of the state of the room (i.e. e1). X's join event is e6.
3. On having joined the room, user X's /sync returns with state of {e1, e6}, and timeline of [e6].
4. X sends a message in the room: e7
5. Alice responds with: e8
6. Meanwhile, X's client should try to fill in the missing history, and calls /messages on B.com which should try to pull in the history from A.com. (It looks like this doesn't happen though, as we saw X has no pagination token, so can't call /messages)
7. user Y on B.com also joins the room

Theory one:
8. On having joined the room, user Y's /sync returns with state of {e1, e6}, and timeline of [e6, e7, e8] - i.e. only the local events for B.com. For some reason js-sdk gets the sender sentinels right for [e6, e7, e8] in the timeline.
9. Then Alice sends another event, e9, and Y's riot applies the wrong sentinel - perhaps because getting confused between 'live' timeline events, and processing the non-live ones it received in the initial /sync response. <-- this seems most likely

Theory two:
8. On having joined the room, user Y's /sync returns with no state, or perhaps even no timeline, due to synapse bugs, but it does have a pagination token.
9. user Y then calls /messages to try to fill in the gap, and receives the local history [e6, e7, e8] and state for {e1, e6}, and applies the sentinels correctly.
10. A synapse bug means that /messages doesn't return a pagination token from /messages, so we can't paginate back further.
11. Alice sends another event, e9, and Y's riot applies the wrong sentinel, because it failed to correctly set a forwards-looking sentinel because it got confused by the initial /sync contents, or something else.

[jryans]

Related: #6944