Cannot verify new session, initiated from either direction #29625

mpeter50 · 2025-03-30T18:20:01Z

Steps to reproduce

I have just logged in on Machine B in Element Web
So I choose to verify with another device
Client says to check an other client of mine to verify the session
For several minutes no verification prompt appears on Machine A in Element Web
Open Settings, Sessions on Machine A Element Web
Navigate to my new, unverified session and click Verify Session
I'm prompted to look on the device I want to verify
For several minutes no verification prompt appears on Machine B in Element Web

Outcome

What did you expect?

I expected to get the verification prompt in the top left corner of Element Web.

What happened instead?

I did not get any such prompt.
Currently, because of #29624, I can not log in and initialize encryption on Machine B.

Operating system

Windows 10 (Machine A) and openSUSE Leap (Machine B)

Browser information

Firefox

URL for webapp

https://riot.grin.hu

Application version

1.11.95

Homeserver

https://matrix.grin.hu

Will you send logs?

Yes

andybalaam · 2025-04-16T14:47:43Z

Thank you for the bug report! I have been investigating this today. I have a couple of discoveries, but no clear explanation yet.

First, Machine A has lots of lines like this in its logs:

2025-03-30T18:48:58.771Z E Failed to process outgoing request 0: M_UNKNOWN: MatrixError: [400] One time key signed_curve25519:redacted already exists. Old key: {"key":"redacted1","signatures":{"@user:server":{"ed25519:redacted2"}}}; new key: {'key': 'redacted3', 'signatures': {'@user:server': {'ed25519:redacted4'}}} (https://example.com/_matrix/client/v3/keys/upload)

So it looks like the one-time keys for that device have got messed up - I don't know whether this might have caused the failure to verify. I don't know why these one-time keys have got messed up, but it will probably be fixed if you sign out and sign in again on Machine A (which makes a new "device") and reset your identity as you sign in.

If that doesn't fix the problem, please could you try sending logs again? The logs we have for Machine A and Machine B don't overlap in time, so I can't actually trace a single verification request through and figure out exactly what happened:

2025-03-30T17:38:08.578Z Machine B's logs start
2025-03-30T18:20:47.312Z Machine B's logs end
2025-03-30T18:38:28.547Z Machine A's logs start
2025-03-30T19:20:15.247Z Machine B's logs end

Notes to myself or whoever looks into this more:

I see logs like this on the receiving side:

2025-03-30T18:15:27.773Z I Ignoring just-received verification request redacted5 which did not start a rust-side verification

The relevant code says:

            // There are multiple reasons this can happen; probably the most likely is that the event is an
            // in-room event which is too old.

mpeter50 · 2025-04-23T14:46:00Z

I have been putting off writing an answer because I currently cant reboot Machine A to boot my windows install.

However, for a week now I suspect that I may have botched up the operating system part of the issue description out of habit. Does the logs perhaps include something (maybe the user agent) that indicate what OS was that coming from?
This matters for me to know which client should I do the next test with. I'm almost confident that I was on my linux system (and so, different browser profile and browser state), but then maybe I didnt make a mistake and I was actually on linux.
Sorry for asking this, but I dont have access to my sent logs, in my understanding.

For now, I have logged out on Machine B, then back in, and I was able to confirm the verification, for which the prompt came very quickly on Machine A linux system, somewhere under 5 seconds. The verification could also be completed in a short time without much waiting.

If I have sent Machine A logs from element-web running in a browser on linux, then I cannot reproduce the issue anymore.

andybalaam · 2025-04-24T10:31:54Z

Machine A is Firefox 131.0 on Windows 10 @mpeter50

Thanks for following up!

mpeter50 · 2025-04-25T18:51:18Z

Ok, I can still reproduce this.
Machine A: Windows 10, Firefox 131 and same browser profile and login session as before.
Machine B: openSUSE Leap, Firefox 134

Logging in on Machine B, after selecting to verify with another device, Machine A still does not show that there is a verification requrest. Sent new logs from both devices, in case it is useful.

First, Machine A has lots of lines like this in its logs:

2025-03-30T18:48:58.771Z E Failed to process outgoing request 0: M_UNKNOWN: MatrixError: [400] One time key signed_curve25519:redacted already exists. Old key: {"key":"redacted1","signatures":{"@user:server":{"ed25519:redacted2"}}}; new key: {'key': 'redacted3', 'signatures': {'@user:server': {'ed25519:redacted4'}}} (https://example.com/_matrix/client/v3/keys/upload)

Currently I dont see such a message in the browser console of Machine A (when filtering for "One time key").

2025-03-30T18:15:27.773Z I Ignoring just-received verification request redacted5 which did not start a rust-side verification

I'm still seeing such logs.

So it looks like the one-time keys for that device have got messed up - I don't know whether this might have caused the failure to verify. I don't know why these one-time keys have got messed up, but it will probably be fixed if you sign out and sign in again on Machine A (which makes a new "device") and reset your identity as you sign in.

It is not critical for me to fix this login session. Would it help your work if I kept being logged in to this session to be able to help with debugging?

richvdh · 2025-04-30T12:01:24Z

@mpeter50 I'm looking at your most recent set of logs. One thing I notice is that the clock on machine A seems to be set two hours in the future. This shouldn't be a major problem, but it certainly makes debugging harder...

richvdh · 2025-04-30T12:10:09Z

From the most recent set of logs:

2025-04-25T18:16:22.351Z login on Machine B completes
2025-04-25T18:36:39.275Z machine B sends verification requests:

2025-04-25T18:36:39.275Z I Sending batch of to-device messages. type=m.key.verification.request txnid=308d8d74cbd14439b907d57b1311ea4f ["@mpeter:grin.hu/AEMWNQYNJH (msgid undefined)","@mpeter:grin.hu/APJWFZMCAL (msgid undefined)","@mpeter:grin.hu/EALDWRFYTQ (msgid undefined)","@mpeter:grin.hu/HLXOHIAISC (msgid undefined)","@mpeter:grin.hu/IBPFTRNTQA (msgid undefined)","@mpeter:grin.hu/IWSNTJSDYL (msgid undefined)","@mpeter:grin.hu/JHBKCYEPLT (msgid undefined)","@mpeter:grin.hu/JYLNIPBBAW (msgid undefined)","@mpeter:grin.hu/OJXIEPRAZZ (msgid undefined)","@mpeter:grin.hu/OMQNZHTGOR (msgid undefined)","@mpeter:grin.hu/QRDAUKDVQI (msgid undefined)","@mpeter:grin.hu/VRYBJNETJJ (msgid undefined)","@mpeter:grin.hu/WWREJTHREP (msgid undefined)","@mpeter:grin.hu/XHAFCNZHTL (msgid undefined)","@mpeter:grin.hu/XOVCJWZGTQ (msgid undefined)","@mpeter:grin.hu/YCGCUFSJXZ (msgid undefined)"]
2025-04-25T18:36:39.275Z D FetchHttpApi: --> PUT https://matrix.grin.hu/_matrix/client/v3/sendToDevice/m.key.verification.request/308d8d74cbd14439b907d57b1311ea4f
2025-04-25T18:36:40.109Z D FetchHttpApi: <-- PUT https://matrix.grin.hu/_matrix/client/v3/sendToDevice/m.key.verification.request/308d8d74cbd14439b907d57b1311ea4f [817ms 200]

2025-04-25T18:36:39.292Z machine A receives, and ignores, verification request:

2025-04-25T20:36:39.292Z D DEBUG matrix_sdk_crypto::machine: Received a to-device event
    at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/matrix-sdk-crypto-0.10.0/src/machine/mod.rs:1293
    in matrix_sdk_crypto::machine::receive_to_device_event with sender="@mpeter:grin.hu" event_type="m.key.verification.request" 
    in matrix_sdk_crypto::machine::receive_sync_changes
2025-04-25T20:36:39.292Z I INFO matrix_sdk_crypto::verification::machine: Received a new verification request
    sender="@mpeter:grin.hu" from_device="QZVAUIEXZM"
    at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/matrix-sdk-crypto-0.10.0/src/verification/machine.rs:341
    in matrix_sdk_crypto::verification::machine::receive_any_event with flow_id="ab3162dfd9e44b138839f35fdc8fc447"
    in matrix_sdk_crypto::machine::receive_to_device_event with sender="@mpeter:grin.hu" event_type="m.key.verification.request" 
    in matrix_sdk_crypto::machine::receive_sync_changes
2025-04-25T20:36:39.306Z D [Perf]: receiveSyncChanges took 14ms
2025-04-25T20:36:39.306Z I Ignoring just-received verification request ab3162dfd9e44b138839f35fdc8fc447 which did not start a rust-side verification

2025-04-25T18:51:57.331Z machine A sends verification request:

2025-04-25T20:51:57.331Z I Sending batch of to-device messages. type=m.key.verification.request txnid=6674781d6ea449378ba86bafd659a1b9 ["@mpeter:grin.hu/QZVAUIEXZM (msgid undefined)"]
2025-04-25T20:51:57.331Z D FetchHttpApi: --> PUT https://matrix.grin.hu/_matrix/client/v3/sendToDevice/m.key.verification.request/6674781d6ea449378ba86bafd659a1b9
2025-04-25T20:51:57.512Z D FetchHttpApi: <-- PUT https://matrix.grin.hu/_matrix/client/v3/sendToDevice/m.key.verification.request/6674781d6ea449378ba86bafd659a1b9 [181ms 200]

2025-04-25T18:52:10.927Z machine B receives, and ignores, verification request:

2025-04-25T18:52:10.927Z D DEBUG matrix_sdk_crypto::machine: Received a to-device event
    at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/matrix-sdk-crypto-0.10.0/src/machine/mod.rs:1293
    in matrix_sdk_crypto::machine::receive_to_device_event with sender="@mpeter:grin.hu" event_type="m.key.verification.request" 
    in matrix_sdk_crypto::machine::receive_sync_changes
2025-04-25T18:52:10.927Z I INFO matrix_sdk_crypto::verification::machine: Received a new verification request
    sender="@mpeter:grin.hu" from_device="IWSNTJSDYL"
    at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/matrix-sdk-crypto-0.10.0/src/verification/machine.rs:341
    in matrix_sdk_crypto::verification::machine::receive_any_event with flow_id="99ce0c3e771344588139bbfb26f175f8"
    in matrix_sdk_crypto::machine::receive_to_device_event with sender="@mpeter:grin.hu" event_type="m.key.verification.request" 
    in matrix_sdk_crypto::machine::receive_sync_changes
2025-04-25T18:52:10.977Z D [Perf]: receiveSyncChanges took 50ms
2025-04-25T18:52:10.977Z I Ignoring just-received verification request 99ce0c3e771344588139bbfb26f175f8 which did not start a rust-side verification

richvdh · 2025-04-30T12:16:51Z

One thing I notice is that the clock on machine A seems to be set two hours in the future. This shouldn't be a major problem, but it certainly makes debugging harder...

In fact, this is (I think) exactly what the problem is. We ignore incoming verification requests with a timestamp more than 10 minutes ago, or more than 5 minutes in the future.

richvdh · 2025-04-30T12:17:34Z

Closing for now as it appears to be due to the incorrect timestamp. Let us know if you still have problems after you fix your clock.

mpeter50 · 2025-04-30T21:27:31Z

@mpeter50 I'm looking at your most recent set of logs. One thing I notice is that the clock on machine A seems to be set two hours in the future. This shouldn't be a major problem, but it certainly makes debugging harder...

Sorry for that. Its because windows insists storing local time in the system clock, even if I tell it to store UTC time there because thats what linux more sensibly does. Nowadays I use linux more, and got tired of researching why windows does not respect the registry settings it should to fix that.

In fact, this is (I think) exactly what the problem is. We ignore incoming verification requests with a timestamp more than 10 minutes ago, or more than 5 minutes in the future.

That makes sense actually. Could you perhaps add a log statement about it?

My clock cannot be fixed because windows is buggy, and for unknown reasons it does not take into account settings (1, 2, 3) that it should.
But I think that in this case it would be fine as a "fix" if the issue was communicated with the user. Perhaps a js console log that those who really want to know the problem can look for, or some kind of notice as a notification in the top-left corner.
I assume that others dualbooting windows and linux might also run into this issue, if you agree the latter approach would be better.

richvdh · 2025-05-01T10:00:22Z

Adding a log line is easy; indeed if you wanted to open a PR that would be appreciated. The location in question is https://github.com/matrix-org/matrix-rust-sdk/blob/main/crates/matrix-sdk-crypto/src/verification/machine.rs#L356; that trace! should probably be debug! or even info!.

The problem is that receiving "old" verification requests is somewhat expected, when you open a client that's been offline for a while, and we don't really want to be bugging the user with verification requests which have long since expired, or with warnings that we are ignoring them.

mpeter50 · 2025-05-02T13:13:37Z

That sounds reasonable, thanks for the explanation. I'll open an MR soon.

In element-hq/element-web#29625 it was found to be useful to give more visibility to this kind of verification error. Signed-off-by: mpeter50 <[email protected]>

mpeter50 added the T-Defect label Mar 30, 2025

dosubot bot added A-E2EE-SAS-Verification O-Uncommon Most users are unlikely to come across this or unexpected workflow labels Mar 30, 2025

florianduros added the S-Major Severely degrades major functionality or product features, with no satisfactory workaround label Apr 1, 2025

richvdh closed this as completed Apr 30, 2025

richvdh changed the title ~~Cannot verifiy new session, initiated from either direction~~ Cannot verify new session, initiated from either direction Apr 30, 2025

mpeter50 mentioned this issue May 2, 2025

Update logging of device verification request timestamp valdiation matrix-org/matrix-rust-sdk#4999

Merged

1 task

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

Cannot verify new session, initiated from either direction #29625

Cannot verify new session, initiated from either direction #29625

mpeter50 commented Mar 30, 2025

andybalaam commented Apr 16, 2025

Uh oh!

mpeter50 commented Apr 23, 2025

Uh oh!

andybalaam commented Apr 24, 2025

Uh oh!

mpeter50 commented Apr 25, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

mpeter50 commented Apr 30, 2025

Uh oh!

richvdh commented May 1, 2025

Uh oh!

mpeter50 commented May 2, 2025

Uh oh!

Uh oh!

Cannot verify new session, initiated from either direction #29625

Cannot verify new session, initiated from either direction #29625

Comments

mpeter50 commented Mar 30, 2025

Steps to reproduce

Outcome

What did you expect?

What happened instead?

Operating system

Browser information

URL for webapp

Application version

Homeserver

Will you send logs?

andybalaam commented Apr 16, 2025

Uh oh!

mpeter50 commented Apr 23, 2025

Uh oh!

andybalaam commented Apr 24, 2025

Uh oh!

mpeter50 commented Apr 25, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

richvdh commented Apr 30, 2025

Uh oh!

mpeter50 commented Apr 30, 2025

Uh oh!

richvdh commented May 1, 2025

Uh oh!

mpeter50 commented May 2, 2025

Uh oh!