Inconsistent behavior and delays when widgets read/receive events in encrypted rooms

[ghost]

Description

Previously, widgets couldn't read/receive room events in end-to-end encrypted rooms (#17615). This was addressed in matrix-org/matrix-react-sdk#6371, but after testing the implementation I noticed that reading and receiving room events has a very different behavior in encrypted rooms than it does in plaintext ones (reading refers to using .readRoomEvents whereas receiving refers to using .on('action:send_event', ...):

• In plaintext rooms you get the last 25 events when reading, but in encrypted rooms you actually get the first 25 that were sent.
• In plaintext rooms you get the events in the reverse order they were sent when reading, but in encrypted rooms they arrive in seemingly random order. Admittedly, this can be solved by sorting them by timestamp, but the behaviour is still different.
• Both when reading and receiving the events arrive with a considerable delay (up to 5 seconds) that's not present in plaintext rooms.
• When reading in plaintext rooms the events are all received at the same time as an array, whereas in encrypted rooms they sometimes arrive one after the other (with a delay in between). I can't reproduce this behaviour right now - but this was definitely happening before.
• In plaintext rooms there's no unread message indicator for events that are not shown in the timeline, but in encrypted rooms there is. This is minor, but still an inconsistency.

Steps to reproduce

• Join an encrypted room
• Send a room event and measure how long it takes to receive it back
• Send some more room events and refresh the page
• Read room events and measure how long it takes to receive them
• Note whether they all arrive at the same time or one by one and in what order
• See if there's an unread message indicator
• Send 50 events and see which 25 you get back when reading - the first 25 or the last 25

In plaintext rooms I receive an event back almost immediately. When I refresh the page and read room events, I get the last 25 almost immediately, all at the same time and in the reverse order they were sent. There's no unread message indicator.

Logs being sent: yes

Version information

• Platform: web (in-browser)
• Browser: Chrome 91.0.4472.114 (Official Build) (arm64)
• OS: macOS 11.4 (20F71)
• URL: develop.element.io

[t3chguy]

I had good hard laugh as the user_id you submitted the rageshake with. Nice

[ghost]

I had good hard laugh as the user_id you submitted the rageshake with. Nice

I do love APIs - when they work. 😂

[turt2live]

@ilovecommits I'm afraid I can't reproduce any of this :(

Encrypted and unencrypted rooms are both returning events in the same order, at the same speed, and from the same side of the timeline. The closest I can reproduce is that it's harder for the unread notification to go away on encrypted rooms, but this is not affected by the widget at all: it would be affected by the user's activity with Element causing it to be dismissed.

I can also see from the logs that the events are being sent in the correct order and with fairly quick speed (200ms after the widget starts setting up the events are being sent).

I'm not sure what you're seeing, but if you can share the widget's code or create a minimal test case to look at then that would be appreciated. If it helps, I've been testing with https://github.com/turt2live/matrix-widget-debug and simple console.log() statements.

[ghost]

@ilovecommits I'm afraid I can't reproduce any of this :(

Encrypted and unencrypted rooms are both returning events in the same order, at the same speed, and from the same side of the timeline. The closest I can reproduce is that it's harder for the unread notification to go away on encrypted rooms, but this is not affected by the widget at all: it would be affected by the user's activity with Element causing it to be dismissed.

I can also see from the logs that the events are being sent in the correct order and with fairly quick speed (200ms after the widget starts setting up the events are being sent).

I'm not sure what you're seeing, but if you can share the widget's code or create a minimal test case to look at then that would be appreciated. If it helps, I've been testing with https://github.com/turt2live/matrix-widget-debug and simple console.log() statements.

I'll check again and see if I can create a test case.

[ghost]

@turt2live, today I wrote a minimal widget implementation and have the following to report:

1. In encrypted rooms old events are received when subscribing with .on(). (In plaintext rooms I had to use .readRoomEvents() to receive them.) After sending some events and refreshing the page, sometimes an incorrect amount of events is received (too few or too many). Also, they're unsorted. After refreshing the page the second time, the correct amount of events is received and in the correct reverse order. Unlike with .readRoomEvents(), I get all events this way, not just the last 25.

2. Sometimes events fail to send for no good reason (can't replicate this behavior intentionally). The error I'm getting in the console is 'Room was previously configured to use encryption, but is no longer'. That happens in a newly-created room.

3. Every time I send an event, I receive this event back. This is normal behavior, but now I'm noticing that I'm sometimes receiving the same event back twice. Again, this is hard to replicate.

4. Everything is slower. Sometimes it takes a few seconds before I receive an event back. Receiving old events with .on() is much slower, because they arrive one by one. Send 200 events, refresh the page and then see how long it takes before they've all arrived. (It's also not possible to opt out of this behaviour and only subscribe to new events.)

5. Not sure if this is related or even an issue, but I get {"isTrusted":false} when I run JSON.stringify() on the whole event. Also, I received some events that caused a JS exception when trying to access the .content property.

6. I previously reported receiving the first (instead of last) 25 events, but this doesn't seem to be an issue anymore (perhaps a bug in my own code).

Here's the test code:

import './App.css';
import { useEffect } from 'react';
import { WidgetApi } from 'matrix-widget-api'
import { useState, useRef } from 'react'

const { widgetId, parentUrl } = window.location.search
.slice(1)
.split('&')
.reduce((p, e) => {
  const [key, value] = e.split('=').map((e) => decodeURIComponent(e));
  return {
    ...p,
    [key]: value,
  };
}, {});

const widgetApi = new WidgetApi(widgetId, parentUrl);

['send', 'receive'].forEach((direction) =>
  widgetApi.requestCapability(`org.matrix.msc2762.${direction}.event:net.nordeck.test`)
);

function App() {
  const [events, setEvents] = useState([]);
  const count = useRef(0)

  useEffect(() => {
    function callback(e) {
      e.preventDefault();
      widgetApi.transport.reply(e.detail, {});
      setEvents(events=>[e.detail.data.content, ...events])
      count.current = Math.max(count.current,e.detail.data.content.count+1)
    }

    widgetApi.on('action:send_event', callback)
    widgetApi.start();

    return () => widgetApi.off('action:send_event', callback)
  }, [])

  return (
      <>
        <h1>{events.length}</h1>
        <button onClick={async () => {
          const events = (await widgetApi.readRoomEvents('net.nordeck.test')).map(e=>e.content) // returns 25 events, newest first
          count.current = events[0].count+1
          setEvents(events)
        }}>Read</button>
        <button onClick={() => {
          widgetApi.sendRoomEvent('net.nordeck.test', {count: count.current++})
        }}>Send</button>
        <button onClick={async () => {
          for(var i=0;i<100;i++) {
            widgetApi.sendRoomEvent('net.nordeck.test', {count: count.current++})
            await new Promise((r) => setTimeout(r, 1000)); // prevent 'Some of your messages have not been sent'
          }
        }}>Send 100</button>
        <pre>
          {JSON.stringify(events,null,2)}
        </pre>
      </>
  );
}

export default App;

[ghost]

@turt2live Is that enough information for you to work with or do you need something else from me?

[turt2live]

sorry, just trying to balance this against everything else that's going on. At a glance, that should be enough information to narrow down the issues though it feels like there's multiple things going on which might end up getting split out to individual issues.

[ghost]

@skolmer suggested that some of the issues I've been facing have to do with me doing a hard refresh (Cmd + R). After testing, I noticed that that after creating a new user account and joining an existing room with events in it, I didn't get all the events. After a delay I got some events and after another delay I got some more. Then I did a hard refresh and only got the first batch.

Going to test further.

[ghost]

Just to exclude the possibility of it being a browser/server/account issue, I created a new Chrome profile, a new user account on matrix.org and a new room on matrix.org. Same result.

[skolmer]

In encrypted rooms old events are received when subscribing with .on().

It took me some time to reproduce this. It looks like it only happens when the caps have already been approved and saved in local storage and if the widget is pinned to the room so it initializes (without delay) directly on refresh of the element client.
If instead the widget is opened just after element is already initialized it does NOT receive any old events via the action:send_event event handler.

so the steps to reproduce are:

1. create a simple widget like in the example above
2. pin the widget to the room
3. approve and save any capabilities required by the widget
4. send some events to the room using the widget
5. refresh element (hard reload is not required - just F5)
6. see old events coming in through the action:send_event handler in random quantity and order. It looks like a race condition - the earlier the initialization of the widget starts the more events are received.