[e2e issue] client badly considers someone is not a room member

[Jean-PhilippeR]

I have found an interesting and systematic issue related to e2e encryption on iOS and synapse.
A creates an e2e room with B
They send messages -> OK.
A invites C
C send a message: A can decrypt this message but not B.
After some investigation. I found the reason. C considers B is not a room member so it does not send him the needed megolm keys.
Problem is linked to MxRoomState -> handleStateEvent. He considers the user is no more part of the room and remove him.
If I have a look on the /sync response received by C just after he has joined the room:

B is in room->joins->state->events with state{ membership = join;type = "m.room.member";} => correct
But in timeline events , the last events we receive related to B is "B has been invited"
But the events related to "B has joined room" is missing even if more recent than event "B has been invited"
Last event in this timeline events is "C has joined room"
I can provide you in isntrumented log if you want.
So For me, there is an issue on Synapse which does not send correct event to C.
But client should be robust to this use case.

To conclude, I will try to implement following work around on client: if a m.room.member event in the timeline event is older than m.room.member state event associated to same member, its should be ignored.
But perhaps this issue concerns all state events.

I have added this check in MxRoomState -> handleStateEvent for RoomMember only. It seems to fix the issue.
Manu, do you think it is an acceptable work around? Or can we fix it in a better way?

[Jean-PhilippeR]

A similar issue occurs despite of client fix

=> Client starts and detect a corruption

[INF][MX ] 08-02 10:15:48.993 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Warning: MXFileStore has been reset due to room file corruption. Room id: !DcIbyxKjjgxAxKtWjD:xxxx.com
[INF][MX ] 08-02 10:15:48.993 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Delete all data
[INF][MX ] 08-02 10:15:49.021 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Loaded room messages of 0 rooms in 28ms
[INF][MX ] 08-02 10:15:49.021 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Loaded room states of 0 rooms in 0ms
[INF][MX ] 08-02 10:15:49.021 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Loaded rooms summaries data of 0 rooms in 0ms
[INF][MX ] 08-02 10:15:49.021 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Loaded rooms account data of 0 rooms in 0ms
[INF][MX ] 08-02 10:15:49.022 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Loaded read receipts of 0 rooms in 0ms
[INF][MX ] 08-02 10:15:49.022 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Loaded 0 MXUsers in 0ms
[INF][MX ] 08-02 10:15:49.022 | 15363 | MATRIX_LOG_WRAPPER | [MXFileStore] Data loaded from files in 30ms

=> It decides to perform an initial /sync again
[INF][MX ] 08-02 10:15:49.310 | 1027 | MATRIX_LOG_WRAPPER | [MXSession] Do an initial /sync
[INF][MX ] 08-02 10:15:49.310 | 1027 | MATRIX_LOG_WRAPPER | [MXHTTPClient] Request 0x171079c00 with method:GET - url:https://matrix.xxxx.com/_matrix/client/r0/sync?access_token=TOKEN - parameters:{
timeout = 0;
}

=> For room "!aBlswEAkTSCrHQisTc:xxxx.com" in room.state it only gets information Jean-philippe RouaultTest is in invite state while he is indeed in joined state!

                        content =                             {
                            "avatar_url" = "<null>";
                            displayname = "Jean-philippe RouaultTest";
                            membership = invite;
                        };
                        "event_id" = "$15016590391065InGQi:xxxx.com";
                        membership = invite;
                        "origin_server_ts" = 1501659039219;
                        sender = "@aa053de698c147e2:xxxx.com";
                        "state_key" = "@b8a8036b9b326a6e:xxxx.com";
                        type = "m.room.member";
                        unsigned =                             {
                            age = 2709373;
                        };

[INF][MX ] 08-02 10:15:49.448 | 1027 | MATRIX_LOG_WRAPPER | [MXSession] Received 2 joined rooms, 0 invited rooms, 0 left rooms in 139ms

=> My first fix detects the event in room.state is obsolet: so it means room.state has been reinitialized because of File system corruption?
=> And somewhere correct room.state has been preserved?
[INF][MX ] 08-02 10:15:51.651 | 1027 | MATRIX_LOG_WRAPPER | [MXEventTimeline] paginate 30 messages in !aBlswEAkTSCrHQisTc:xxxx.com (10 are retrieved from the store)
[INF][MX ] 08-02 10:15:51.652 | 1027 | MATRIX_LOG_WRAPPER | [MxRoomState] The room member event is obsolet -> ignore it: event $15016590391066RpSNq:xxxx.com: m.room.member - 2017-08-02 07:30:39 +0000: {
displayname = "Jean-philippe RouaultTest";
membership = invite;
}, state key @ea8e9eaca2cf5557:xxxx.com and sender @aa053de698c147e2:xxxx.com

=> client decides to get oldest messages in room !aBlswEAkTSCrHQisTc:xxxx.com (a consequence of initial sync??)
[INF][MX ] 08-02 10:15:51.732 | 1027 | MATRIX_LOG_WRAPPER | [MXHTTPClient] Request 0x171272980 with method:GET - url:https://matrix.xxxx.com/_matrix/client/r0/rooms/!aBlswEAkTSCrHQisTc:xxxx.com/messages?access_token=TOKEN - parameters:{
dir = b;
from = "t10-10260_30022_330_3559_1378_6_1215_1703";
limit = 30;

And get again event Jean-philippe RouaultTest is invited and not Room Member
{
age = 2711733;
content = {
"avatar_url" = "";
displayname = "Jean-philippe RouaultTest";
membership = invite;
};
"event_id" = "$15016590391065InGQi:xxxx.com";
membership = invite;
"origin_server_ts" = 1501659039219;
"room_id" = "!aBlswEAkTSCrHQisTc:xxxx.com";
sender = "@aa053de698c147e2:xxxx.com";
"state_key" = "@b8a8036b9b326a6e:xxxx.com";
type = "m.room.member";
unsigned = {
age = 2711733;
};
"user_id" = "@aa053de698c147e2:xxxx.com";
},
=> For a reason I don't know, my fix does not work here. User is removed.

[INF][MX ] 08-02 10:15:51.798 | 1027 | MATRIX_LOG_WRAPPER | [MxRoomState] The user is no more part of the room : event $15016590391065InGQi:xxxx.com: m.room.member - 2017-08-02 07:30:39 +0000: {
displayname = "Jean-philippe RouaultTest";
membership = invite;
}, state key @b8a8036b9b326a6e:xxxx.com and sender @aa053de698c147e2:xxxx.com

=> And next encrypted messages will not be readable for Jean-Philippe

[Jean-PhilippeR]

For back pagination management, if I understand well, when you go back in the room history, client really update real room state associated to room to reflect its state in the past.
Example:
Current room state -> Member A has joined room
Room State 1 day before -> member A is only invited

if you go back from 1 day in room history (by using a past timeline), matrix client will really remove (temporaly) member A from room state -> member.

When you work with past timeline, would it be possible to backup current room state before to update it or to only work with a copy of current room state. So that there is no side effect or possibel current room state corruption.
Perhaps it is already the case, but when I see how to client SDK reacts to current server issue, I have a doubt.

[manuroe]

@Jean-PhilippeR room state copies are already made with

matrix-ios-sdk/MatrixSDK/Data/MXEventTimeline.m

Line 725 in 6b656ba

- (void)cloneState:(MXTimelineDirection)direction

When you paginate in a room, there are two live instances of MXRoomState. The one returned by MXRoom.state, which represents the current state of the room, and one that is moving. It represents the state at the current position in the pagination.

[Jean-PhilippeR]

Good :)
So, perhaps the fix I have made should be only done when we work on real room state, not on its clone. I don't know if it is easy to make the difference.

[manuroe]

You need to look at the right direction :) and the property MXEventTimeline.isLiveTimeline.

The MXTimelineDirectionForwards direction and isLiveTimeline = YES means that we are getting events that will update the live timeline.
MXRoom.state and MXRoom.liveTimeline.state are the same thing. MXRoom.state is just a shortcut.

[Jean-PhilippeR]

Thanks. I will try to improve my fix with additional checks.

Did you understand in the logs I have reported why my fix has worked the first time (08-02 10:15:51.652) but not the second time (at 08-02 10:15:51.798)?
Is it because first time the code was executed during a /sync request and the second time during a /room/messages request? Any link with these 2 timelines?

[Jean-PhilippeR]

I am a little confused with MxRoomState._isLive and [MXTimelineDirectionForwards direction and isLiveTimeline = YES.]
Is MxRoomStet._IsLive set to TRUE only if [MXTimelineDirectionForwards direction and isLiveTimeline = YES.], or not?
Should my fix only be performed when _IsLive = TRUE or not?

I am not sure because when you perform a full sync I am not sure _IsLive is set to TRUE and I believe that my fix should be performed during a full sync.

[Jean-PhilippeR]

To get info [MXTimelineDirectionForwards direction and isLiveTimeline = YES.] I need to move my check in MxEventTimeline->handleStateEvent, right? But in this function there is already a check based on [MXTimelineDirectionForwards direction and isLiveTimeline
https://github.com/matrix-org/matrix-ios-sdk/blob/6b656ba7baafc4d77c36492d8d8d3b8b1899d40c/MatrixSDK/Data/MXEventTimeline.m#L755
But it is performed after calling roomState handleStateEvent.
So I will move my check before this calling.

Do you agree? Or shall we rework whole MxEventTimeLine -> handleStateEvent?

For me this check shall be performed if it is Live Timeline, whatever direction is. Why to restrict it to Forward Direction?

[Jean-PhilippeR]

This is another test cas easily reproductible when my fix cannot work
A creates a Room XX with B and C
B leaves the room
A reinvites B => messages sent by B cannot be decrypted by C.

Same reason: On first sync after B has joined again room:

• in /sync response -> Room -> state -> events -> C is only seen has invited
• in /sync response -> Room -> timeline -> events -> events C has joined room is not visible
• in /sync response limited = 1 is set.

This PR is for iOS SDK. Should I create a PR dedicated to synapse?

[erikjohnston]

So I think I repro'ed this with, the crucial bit is the history visibility:

1. A, B share an e2e room with history visibility to set to "joined" (i.e., off)
2. C is invited.
3. B leaves
4. C accepts invite
5. B gets invited by A and rejoins.
6. B's sync has C's join in state but only the C's invite in timeline

This is due to theoretically B not being allowed to see C's join as B wasn't joined at that point. This is meant to be handled by it turning up in state, but that then that gets clobbered by the timeline.

(I will try and write an integration test for this to confirm.)

[erikjohnston]

I've also repro'ed:

1. A, B share an e2e room with history visibility to set to "joined" (i.e., off)
2. C is invited.
3. A sends lots and lots of messages
4. B leaves
5. C accepts invite
6. B gets invited by A and rejoins.
7. B's sync has C's invite in state but no sign of C's join

[erikjohnston]

This is fixed on develop of synapse: matrix-org/synapse#2451 and tested in: matrix-org/sytest#385