Call failures: Bad Encrypted Message on Olm session

[dbkr]

Steps to reproduce

Sometimes, we'll see calls get stuck in the 'connecting' state and take 30 seconds or sometimes several minutes to connect. We observe the following:

• Client A sends and invite and a candidates event, either setting up a new olm session or on an existing one. We see the olm sender chain being incremented for each of these messages as we would expect.
• Client B sends an answer. Again, we see the sender chain incremented as expected on client B but when client A tried to decrypt this message, we get a OLM.BAD_MESSAGE_MAC error from olm. We can also see that another receiver chain has appeared on client A, at index 1.

Example:

client A:
2023-01-05T12:35:08.701Z I Started new olm sessionid W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ for device @cyan-*******:call.ems.host:OOEWTAENVG
2023-01-05T12:35:08.701Z I Started Olm sessions for 1 devices
2023-01-05T12:35:08.705Z I [olmlib.encryptMessageForDevice] Using Olm session W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ for device @cyan-*******:call.ems.host:OOEWTAENVG
2023-01-05T12:35:08.707Z I encryptMessage: Olm Session ID W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ to DELFdJHv1Up6BFoHX0PXbOrXQYy1SbKnhJM89ecZPXA: sender chain index: 0 receiver chain indices: skipped message keys:

2023-01-05T12:35:08.735Z I [olmlib.encryptMessageForDevice] Using Olm session W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ for device @cyan-*******:call.ems.host:OOEWTAENVG
2023-01-05T12:35:08.735Z I encryptMessage: Olm Session ID W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ to DELFdJHv1Up6BFoHX0PXbOrXQYy1SbKnhJM89ecZPXA: sender chain index: 1 receiver chain indices: skipped message keys:

2023-01-05T12:35:09.543Z I decryptMessage: Olm Session ID W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ from DELFdJHv1Up6BFoHX0PXbOrXQYy1SbKnhJM89ecZPXA: sender chain index: 0 receiver chain indices: 1 skipped message keys:
2023-01-05T12:35:09.546Z W Error decrypting event (id=undefined type=m.room.encrypted sender=@cyan-*******:call.ems.host): DecryptionError[msg: Bad Encrypted Message, sender: DELFdJHv1Up6BFoHX0PXbOrXQYy1SbKnhJM89ecZPXA, err: Error: Error decrypting non-prekey message with existing sessions: {"W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ":"OLM.BAD_MESSAGE_MAC"}]

client B:
2023-01-05T12:35:08.787Z I created new inbound Olm session ID W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ with V7LsH4/Jbgbfkq/9LCRbXW48FEXfFGOrto0zqu4dczY
2023-01-05T12:35:08.894Z I decryptMessage: Olm Session ID W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ from V7LsH4/Jbgbfkq/9LCRbXW48FEXfFGOrto0zqu4dczY: sender chain index: 0 receiver chain indices: 1 skipped message keys:
2023-01-05T12:35:08.895Z I Decrypted Olm message from V7LsH4/Jbgbfkq/9LCRbXW48FEXfFGOrto0zqu4dczY with session W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ

2023-01-05T12:35:09.218Z I [olmlib.encryptMessageForDevice] Using Olm session W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ for device @black-*******:call.ems.host:NROZQNGSLY
2023-01-05T12:35:09.220Z I encryptMessage: Olm Session ID W1Shp6zOhkxOZdadkoMnVHZy6sEanhTdFJid33793uQ to V7LsH4/Jbgbfkq/9LCRbXW48FEXfFGOrto0zqu4dczY: sender chain index: 0 receiver chain indices: 2 skipped message keys:

Outcome

What did you expect?

Calls connects speedily

What happened instead?

Call eventually connects, after the calling client tries repeatedly, with js-sdk automatically forcing a new olm session when it gets bad encrypted messages.

Operating system

No response

Browser information

No response

URL for webapp

No response

Will you send logs?

Yes

[fkwp]

Let's try Element R to resolve this issue