livekit / client-sdk-js

LiveKit browser client SDK (javascript)
https://livekit.io
Apache License 2.0
335 stars 146 forks source link

Stopping screen share sometimes breaks e2ee #973

Open revertiz opened 9 months ago

revertiz commented 9 months ago

Describe the bug When couple participants stop screen sharing (possibly in a quick succession) the e2ee breaks and a random 1-2 tracks are not decrypted

Server

Client

To Reproduce Steps to reproduce the behavior:

The steps are a bit unclear and reproduce is not easy, but the general idea is:

  1. many (5+) participants join the room
  2. more than 2 participants share screen
  3. stopping 2 or more screen shares (possibly in a quick succession)
  4. some participants' camera or screen share tile appears not decrypted

Expected behavior e2ee continues to work for every participant

Screenshots If applicable, add screenshots to help explain your problem. image

Additional context I can reproduce both in my app and in livekit demo page (https://meet.livekit.io/)

davidzhao commented 9 months ago

could you confirm if this still happens with the latest server? you are using 1.2.7, which is quite old

revertiz commented 9 months ago

could you confirm if this still happens with the latest server? you are using 1.2.7, which is quite old

Sorry, the version is 1.5.1, updated

arnasledev commented 9 months ago

up! this is important - any ideas whats happening?

devosonder commented 8 months ago

+1

davidzhao commented 8 months ago

This looks to be a bug with the JS client SDK. moving the issue there.

lukasIO commented 8 months ago

I tried to reproduce the issue with the steps outlined in the description, but it continued to work for me in all cases (tried ~5 times of sharing screen from two participants with 5 in the room). Are all participants using the same browser or did you notice this occuring more frequently with a certain browser combination?

raphaelluchini commented 8 months ago

It's happening with some of our users where one of them was using IPad, but I couldn't reproduce either. We just updated the SDK and Server to the latest versions and we will continue to investigate.

AurimasG12 commented 7 months ago

+1

lukasIO commented 7 months ago

@AurimasG12 do you have a way to reproduce this?

arnasledev commented 7 months ago

we have found a way to reproduce it - we all jumped into the room, we all started sharing multiple screens (our app allows that) and then on the count of 3, we started stopping shared screens by leaving only 1 from each participant. One guy stopped all his screens at once (he had 4 shared screens). I'm adding a video how everything went and also the logs from our loki (both in json and txt)

video: https://we.tl/t-N3EiB8AOK3

logs: Explore-logs-2024-02-05 15_35_01.txt Explore-logs-2024-02-05 15_34_27.json

lukasIO commented 7 months ago

oh, that's great! thank you, for e2ee the server logs are unfortunately not very telling, could you also post client debug logs of

lukasIO commented 7 months ago

it would be really helpful if you could, in addition, set debug level also for the lk-e2ee logger with setLogLevel('debug', 'lk-e2ee')

revertiz commented 7 months ago

Hey, we set the log level as suggested and reproduced.

Broken screen for participant with id: dcc89602-fdba-4818-b78f-9f83c3449f92
. Logs: Dooman-ignasp-local.front-4229.pr.meedio.pro-1707819812604.log

Participants that see broken screen: 0a14c645-1719-4ab9-a0b6-186b4e40dbb2, 117d568a-f3fb-4a0e-8eb2-9d92d5e63033, c6cbde2c-2cbd-4b39-8d50-28d4de57f186, 47cfb99b-23d4-4d01-91dc-3ec62a5aee8e
 Logs: Titas-ignasp-local.front-4229.pr.meedio.pro-1707819790409.log IgnasB-ignasp-local.front-4229.pr.meedio.pro-1707819802823.log Aurimas-ignasp-local.front-4229.pr.meedio.pro-1707819764415.log Svajunas-ignasp-local.front-4229.pr.meedio.pro-1707819762602.log

Participant that doesn’t see broken screen: d6acd8a1-1a54-4d48-aa32-b7a66ae3b54b Logs: IgnasP-ignasp-local.front-4229.pr.meedio.pro-1707820541257.log Video: https://we.tl/t-9TJ6kboLId

lukasIO commented 7 months ago

thanks! are you using the ExternalE2EEKeyProvider or a modified/custom version ? Could you also elaborate on when you call setKey on the key provider and whether that key ever changes?

lukasIO commented 7 months ago

I see some errors when trying to decrypt

12:16:27.510 livekit-client.e2ee.worker.mjs:1043 TypeError: Destination stream closed
    at yUe.<anonymous> (index-a4841935.js:1205:66344)
    at Generator.next (<anonymous>)
    at index-a4841935.js:1171:39721
    at new Promise (<anonymous>)
    at ye (index-a4841935.js:1171:39518)
    at yUe.handleReceiver (index-a4841935.js:1205:65753)
    at yUe.setupE2EEReceiver (index-a4841935.js:1205:65482)
    at YUe.<anonymous> (index-a4841935.js:1205:63527)
    at Pr.emit (index-a4841935.js:1171:42543)
    at YUe.emit (index-a4841935.js:1207:135702)
(anonymous) @ livekit-client.e2ee.worker.mjs:1043
Promise.catch (async)
setupTransform @ livekit-client.e2ee.worker.mjs:1042
onmessage @ livekit-client.e2ee.worker.mjs:1628
Show 3 more frames
Show less
12:16:27.516 console.js:213 InternalError: Destination stream closed
overrideMethod @ console.js:213
onWorkerMessage @ livekit-client.esm.mjs:14443
Show 2 more frames
Show less
12:16:27.516 livekit-client.esm.mjs:23124 room event encryptionError {room: 'f4a2314a-cbc1-4d2f-b573-465b69fbb7ca', roomSid: 'RM_AE7x4GgZ4UTs', identity: '117d568a-f3fb-4a0e-8eb2-9d92d5e63033', event: 'encryptionError', args: Array(1)}

This should however have no impact for longer than a frame (it only shows up twice in the whole session) and also the participant that continued to see the screen share has the same errors in their logs. So it's unlikely that this is the root issue.

revertiz commented 7 months ago

thanks! are you using the ExternalE2EEKeyProvider or a modified/custom version ? Could you also elaborate on when you call setKey on the key provider and whether that key ever changes?

using ExternalE2EEKeyProvider from 'livekit-client'. We create Room instance and set the key (setKey) and E2EEEnabled (setE2EEEnabled(true)) immediately.

lukasIO commented 7 months ago

got it. I can't see anything unexpected in the logs. I audited the code paths that get executed when a track gets unpublished/unsubscribed and found a potential edge case. Could you try if it still repros for you with the changes in https://github.com/livekit/client-sdk-js/pull/1032 ?

revertiz commented 6 months ago

got it. I can't see anything unexpected in the logs. I audited the code paths that get executed when a track gets unpublished/unsubscribed and found a potential edge case. Could you try if it still repros for you with the changes in #1032 ?

Hey, we've updated the client version to v2.0.3, which includes the changes from #1032. Unfortunately, the problem still persists

lukasIO commented 6 months ago

v2.0.4 has some (very) verbose e2ee logs. It'll be hard to sift through them, but another repro on that version with setLogLevel('debug', 'lk-e2ee') would be great. The important part would be that the log context is fully present in those logs. You should be able to get those by right-clicking in the js developer console and clicking "save".

revertiz commented 6 months ago

Hey, sorry for the delay, we reproduced on client v2.0.7

Participants with broken e2ee: paulius_log.log dooman_log.log

Participants that didn't see anything wrong: ovi_log.log auri_log.log svajuno_log.log ignas_log.log

Complementary video (of participant without visible broken e2ee): https://we.tl/t-3IES9Tca1N

lukasIO commented 6 months ago

thanks! Did the e2ee display for paulius and dooman break only of one participant? And if so, is that participant @shq9agyxow:matrix.meedio.pro:DFLHOQSHFI for paulius and @red-similar-barracuda:matrix.meedio.pro:LDYGUMTRTH for dooman?

If not, can you tell me which tracks broke for paulius and dooman respectively?

dropping some filtered logs here around what looks like an issue with transceiver reuse

06:13:50.992 livekit-client.e2ee.worker.mjs:1047 Setting up frame cryptor transform {operation: 'decode', passedTrackId: 'TR_VScqUdXi2jor7A', codec: 'vp8', participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: undefined, …}
06:14:15.353 livekit-client.esm.mjs:23960 room event trackUnsubscribed {room: '!ydFiczgktCZrUaMDUK:matrix.meedio.pro', roomID: 'RM_2JyNYg9KrVAS', participant: '@pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL', pID: 'PA_ftdYYjJBuYgL', event: 'trackUnsubscribed', …}
06:14:15.354 livekit-client.esm.mjs:23960 room event trackSubscriptionStatusChanged {room: '!ydFiczgktCZrUaMDUK:matrix.meedio.pro', roomID: 'RM_2JyNYg9KrVAS', participant: '@pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL', pID: 'PA_ftdYYjJBuYgL', event: 'trackSubscriptionStatusChanged', …}
06:14:15.354 livekit-client.e2ee.worker.mjs:1010 unsetting participant {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:14:15.354 livekit-client.esm.mjs:23960 room event trackUnpublished {room: '!ydFiczgktCZrUaMDUK:matrix.meedio.pro', roomID: 'RM_2JyNYg9KrVAS', participant: '@pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL', pID: 'PA_ftdYYjJBuYgL', event: 'trackUnpublished', …}06:14:54.110 livekit-client.esm.mjs:20549 update publication info {trackID: 'TR_VScqUdXi2jor7A', enabled: true, muted: false, trackInfo: {…}, info: ZFe.s}
06:14:54.110 livekit-client.esm.mjs:20549 update publication info {trackID: 'TR_VScqUdXi2jor7A', enabled: true, muted: false, trackInfo: {…}, info: ZFe.s}
06:14:54.110 livekit-client.esm.mjs:22348 received a second track publication for @shq9agyxow:matrix.meedio.pro:DFLHOQSHFI with the same source: screen_share {rpID: 'PA_L29C7pPnGkDF', remoteParticipant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', oldTrack: {…}, newTrack: {…}}
06:14:54.649 livekit-client.e2ee.worker.mjs:1047 Setting up frame cryptor transform {operation: 'decode', passedTrackId: 'TR_VScqUdXi2jor7A', codec: 'vp8', participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', …}
06:15:26.574 livekit-client.e2ee.worker.mjs:1166 enqueue SIF {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.608 livekit-client.e2ee.worker.mjs:1166 enqueue SIF {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.641 livekit-client.e2ee.worker.mjs:1166 enqueue SIF {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.673 livekit-client.e2ee.worker.mjs:1166 enqueue SIF {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.707 livekit-client.e2ee.worker.mjs:1166 enqueue SIF {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.739 livekit-client.e2ee.worker.mjs:1166 enqueue SIF {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.783 livekit-client.esm.mjs:20549 update publication info {trackID: 'TR_AM6Y2ejf9RMTfV', enabled: true, muted: false, trackInfo: {…}, info: ZFe.s}
06:15:26.783 livekit-client.esm.mjs:20549 update publication info {trackID: 'TR_VCFRo2zWvksxuw', enabled: true, muted: false, trackInfo: {…}, info: ZFe.s}
06:15:26.783 livekit-client.esm.mjs:20549 update publication info {trackID: 'TR_VScqUdXi2jor7A', enabled: true, muted: false, trackInfo: {…}, info: ZFe.s}
06:15:26.784 livekit-client.esm.mjs:23960 room event trackUnsubscribed {room: '!ydFiczgktCZrUaMDUK:matrix.meedio.pro', roomID: 'RM_2JyNYg9KrVAS', participant: '@pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL', pID: 'PA_ftdYYjJBuYgL', event: 'trackUnsubscribed', …}
06:15:26.784 livekit-client.esm.mjs:23960 room event trackSubscriptionStatusChanged {room: '!ydFiczgktCZrUaMDUK:matrix.meedio.pro', roomID: 'RM_2JyNYg9KrVAS', participant: '@pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL', pID: 'PA_ftdYYjJBuYgL', event: 'trackSubscriptionStatusChanged', …}
06:15:26.784 livekit-client.e2ee.worker.mjs:1010 unsetting participant {participant: '@shq9agyxow:matrix.meedio.pro:DFLHOQSHFI', mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.784 livekit-client.esm.mjs:23960 room event trackUnpublished {room: '!ydFiczgktCZrUaMDUK:matrix.meedio.pro', roomID: 'RM_2JyNYg9KrVAS', participant: '@pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL', pID: 'PA_ftdYYjJBuYgL', event: 'trackUnpublished', …}
06:15:26.830 livekit-client.e2ee.worker.mjs:1161 skipping empty frame {participant: undefined, mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.841 livekit-client.e2ee.worker.mjs:1161 skipping empty frame {participant: undefined, mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:26.958 livekit-client.e2ee.worker.mjs:1161 skipping empty frame {participant: undefined, mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:27.059 livekit-client.e2ee.worker.mjs:1161 skipping empty frame {participant: undefined, mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
06:15:27.080 livekit-client.e2ee.worker.mjs:1161 skipping empty frame {participant: undefined, mediaTrackId: 'TR_VScqUdXi2jor7A', fallbackCodec: 'vp8'}
revertiz commented 6 months ago

Did the e2ee display for paulius and dooman break only of one participant? And if so, is that participant @shq9agyxow:matrix.meedio.pro:DFLHOQSHFI for paulius and @red-similar-barracuda:matrix.meedio.pro:LDYGUMTRTH for dooman?

Paulius : @pink-careful-anglerfish:matrix.meedio.pro:TDZFDRTEXL K6admin(dooman): @shq9agyxow:matrix.meedio.pro:DFLHOQSHFI Ovi: @pink-preliminary-flea:matrix.meedio.pro:MREMYMAADW svajunas: @copper-condemned-locust:matrix.meedio.pro:PJASLXOGVM ignas: @7z74jll4pc:matrix.meedio.pro:PRTXHSDUYQ auri: @red-similar-barracuda:matrix.meedio.pro:LDYGUMTRTH

not 100% that only 1 participant broke, as some tiles had their video feeds muted. But can confirm that this participant(dooman) @shq9agyxow:matrix.meedio.pro:DFLHOQSHFI broke for paulius

lukasIO commented 5 months ago

got it, I added some sanity checks and some logs specifically to give more insight for this issue in https://github.com/livekit/client-sdk-js/pull/1082.

revertiz commented 5 months ago

Hi, @lukasIO, do you need more tests for this?

lukasIO commented 5 months ago

Yeah, we still weren't able to repro this. If you can repro with the changes from #1082 (they're released in the latest client version) we would get more info on what's going on. Sorry for this dragging on for so long, but it's really tricky to debug without a way to repro it on our side.

revertiz commented 5 months ago

Client version: 2.0.10

Participant ids: Svajunas @gxhiwckl6j:matrix.meedio.pro:JXLGKHKYKW
 Aurimas @black-supposed-prawn:matrix.meedio.pro
 Ignas @7z74jll4pc:matrix.meedio.pro:DNDMIYKWMH Ovidijus @7g5tcf49w7:matrix.meedio.pro:DNLNWJCDXZ Paulius @cyan-unsightly-walrus:matrix.meedio.pro

Logs (e2ee for screenshare tile breaks at ~12:39:38): svajunas-broken.log aurimas.log ovidijus.log paulius.log Ignasp.log

Video (Ignas): https://we.tl/t-jdcjlnnMEu

lukasIO commented 5 months ago

@revertiz thank you, that's helpful. Some of the logs are unfortunately truncated due to the browsers log export function. Do you happen to have server logs for this session, too? You can also share them with me on the LiveKit community slack in a PM.

revertiz commented 5 months ago

Sent you over PM in slack

revertiz commented 4 months ago

Hey @lukasIO, any news on this?

lukasIO commented 4 months ago

Unfortunately no news yet.

Gulianrdgd commented 2 months ago

I don't know If this helps. You can delete otherwise. I am implementing my own video calling application. And I have found that the video stream works and i can see the camera stream in a <video> element. But when I right-click on it and press pause, wait a bit and then press play again. I also get this behavior.

No decryption error in the logs. (with setLogLevel('debug', 'lk-e2ee');)

Screenshot from 2024-06-26 15-39-04