vincenth's riot-web didn't share megolm keys with the right olm devices

[ara4n]

https://github.com/matrix-org/riot-web-rageshakes/issues/1973

• vincent invited valere to a DM
• vincent's device correctly downloaded valere's device list (and his own).
• LL logs this (is 0 members for room significant)?

2019-11-25T11:29:43.009Z I Device list for @valere:vector.modular.im now up to date
2019-11-25T11:29:43.029Z I LL: got 2 members from server for room !zJKJJDNyfSfpondTLZ:matrix.org
2019-11-25T11:29:43.029Z I LL: RoomState about to set 2 OOB members ...
2019-11-25T11:29:43.029Z I LL: RoomState put in OOB_STATUS_FINISHED state ...
2019-11-25T11:29:43.029Z I LL: telling store to write 0 members for room !zJKJJDNyfSfpondTLZ:matrix.org

• vincent turns on E2E.
• vincent sends some messages, which starts a new megolm session which apparently only gets sent to a single device (vincent's OTWDCAOETJ):

2019-11-25T11:30:22.343Z I Enabling encryption in !zJKJJDNyfSfpondTLZ:matrix.org
2019-11-25T11:30:53.890Z I [Media Config] Fetching
2019-11-25T11:30:54.509Z I [Media Config] Fetched config: {"m.upload.size":104857600}
2019-11-25T11:30:54.516Z I Starting load of AsyncWrapper for modal
2019-11-25T11:30:56.156Z W Returning only the content-uri from uploadContent(). Future versions of the js-sdk will change this default, to return the whole response object. Set opts.onlyContentUri=false to change this behaviour now.
2019-11-25T11:30:56.482Z I sendEvent of type m.room.message in !zJKJJDNyfSfpondTLZ:matrix.org with txnId m1574681456482.33
2019-11-25T11:30:56.504Z I Starting to track devices for room !zJKJJDNyfSfpondTLZ:matrix.org ...
2019-11-25T11:30:56.504Z I setting pendingEvent status to encrypting in !zJKJJDNyfSfpondTLZ:matrix.org
2019-11-25T11:30:56.516Z I Starting to encrypt event for !zJKJJDNyfSfpondTLZ:matrix.org
2019-11-25T11:30:56.516Z I downloadKeys: already have all necessary keys
2019-11-25T11:30:56.517Z I Starting new megolm session for room !zJKJJDNyfSfpondTLZ:matrix.org
2019-11-25T11:30:56.643Z I share keys with device @vincent_houlot:matrix.org:OTWDCAOETJ
2019-11-25T11:30:56.671Z I Using sessionid ZDuRhWzQWjjHuos8ig6JDXUQYdUFrW16LEPRs2r/Wcw for device @vincent_houlot:matrix.org:OTWDCAOETJ
2019-11-25T11:30:56.675Z I Session ID ZDuRhWzQWjjHuos8ig6JDXUQYdUFrW16LEPRs2r/Wcw to /DFaR18en9FafpIrI6g+ecAxUFBqF0ZT2LToYH+YIAs: sender chain index: 1 receiver chain indices: 2 5 5 14 2 skipped message keys: 28 27
2019-11-25T11:30:56.881Z I Completed megolm keyshare in !zJKJJDNyfSfpondTLZ:matrix.org (slice 1/1)

• subsequently valere joins, and can't read previous messages; he tries to keyshare req them from vincent, but apparently the megolm session was never shared with valere, so the client refuses to reshare:

2019-11-25T13:16:19.404Z I Join event for @valere:vector.modular.im in !zJKJJDNyfSfpondTLZ:matrix.org
2019-11-25T13:16:19.414Z I Marking device list outdated for @valere:vector.modular.im
2019-11-25T13:16:19.414Z I Starting key download for ["@valere:vector.modular.im"]
2019-11-25T13:16:19.473Z I got keys for @valere:vector.modular.im: {...all the correct keys...}
2019-11-25T13:16:19.475Z I Completed key download for @valere:vector.modular.im
2019-11-25T13:16:19.475Z I Device list for @valere:vector.modular.im now up to date
2019-11-25T13:16:19.926Z I Saving device tracking data at token s1167666233_757269613_16147_386955877_234541993_1001262_36026604_18904250_63982
2019-11-25T13:16:23.569Z I m.room_key_request from @valere:vector.modular.im:NWIPWJJWXK for !zJKJJDNyfSfpondTLZ:matrix.org / ip0lN4JbiXIGmM5Od5Pv+VC62L6JiKyTTjKpkZ+9UVk (id m1574687787418.34)
2019-11-25T13:16:23.570Z I Session ID ip0lN4JbiXIGmM5Od5Pv+VC62L6JiKyTTjKpkZ+9UVk never shared with user @valere:vector.modular.im

• Subsequent messages from vincent get a new outbound megolm session, but it's not shared with valere (or any of vincent's other devices, seemingly).

I have no idea why vincent's client is failing to send the megolm keys to the various devices in the room.

[ara4n]

It's almost like any attempts to share keys for this room silently fail out after the initial attempt.

2019-11-25T11:30:56.643Z I share keys with device @vincent_houlot:matrix.org:OTWDCAOETJ

[ara4n]

I think to have a hope of debugging this without jaeger, we should be logging:

• fixing the logs to distinguish megolm from olm sessions (rather than using the ambiguous term "session")
• Which megolm session ID we're using to encrypt messages
• Which megolm session ID we're trying to share over which Olm sessions
• Which devices we think are in a room whenever we start a new megolm session ID

Separately, it'd also be really useful to track:

• When we successfully respond to a keyshare request
  • actually we do, we say: "Re-shared key for session" and "device is already verified: sharing keys"
• When we resolve a UISI, whether it's because we received a megolm session via keyshare response or via initial megolm session setup (would have been useful in an earlier problem)

[turt2live]

Considering a duplicate of #3846