search

bigbluebutton / bigbluebutton

Complete open source web conferencing system.
https://bigbluebutton.org
GNU Lesser General Public License v3.0
8.57k stars 5.96k forks source link

Webcam shutting down randomly #12061

Closed ch9hn closed 2 years ago

ch9hn commented 3 years ago

We have some errors in the HTML5 frontend, when launching some webcam streams in different tabs. The webcams shut down randomly in the frontend. Version is v2.3-beta-3 bbb-html5 1:2.3.0-1588

Node Frontend Processes: 8 Node Backend Processes: 4

Ive tested it with 2 frontend and 2 backend processes, still the issue. But with 1 frontend and 1 backend process, the issues are appearing not so often. So it might be a race condition which is not propper fixed currently.

33be85a22d2f22e296ed6834a99498ae9ebaa03c.js?meteor_js_resource=true:331 Uncaught (in promise) TypeError: Cannot set property 'started' of undefined
    at WebRtcPeerSendonly.<anonymous> (33be85a22d2f22e296ed6834a99498ae9ebaa03c.js?meteor_js_resource=true:331)
    at 33be85a22d2f22e296ed6834a99498ae9ebaa03c.js?meteor_js_resource=true:1
(anonymous) @ 33be85a22d2f22e296ed6834a99498ae9ebaa03c.js?meteor_js_resource=true:331
(anonymous) @ 33be85a22d2f22e296ed6834a99498ae9ebaa03c.js?meteor_js_resource=true:1
basisbit commented 3 years ago

Could you please check on your client if maybe it already hit its CPU limit with the different browser tabs showing and capturing webcams?

This has probably nothing to do with nodejs, but if at all (if it is not a client issue), is more likely related to Kurento.

ch9hn commented 3 years ago

Thank you for your reply, i tested it on my modern AMD Ryzen 6 Core (12 HT) machine. Even with a bare metal 64 core machine, the errors are occurring.

basisbit commented 3 years ago

I was referring to your client which is running the webbrowsers, not your server which is running the BigBlueButton service.

ch9hn commented 3 years ago

That are the specs of my clients which are testing against the BigBlue Button Server. The 6 Core machine is my local pc, the 64 machine is a dedicated bare metal for tests.

prlanzarin commented 3 years ago

Please attach full server side logs (/var/log/syslog, /var/log/bbb-webrtc-sfu/, /var/log/kurento-media-server/, /var/log/bbb-apps/akka/, /var/log/nginx/html5-client.log [if this one existis]) for a day where you could reproduce the issue.

If you're in the position to send those, put them in a tarball in their full. Do not crop them in any form.

prlanzarin commented 3 years ago

Moreover: how are you sharing webcams across multiple tabs of a browser instance? Is it with fake, pre-built media from a Chromium browser or are you pulling video from a real device (a webcam)?

Also: you did not state what browser and version you're using. Would also be helpful to know how many cameras you're trying to share in a single session. And whether pagination is configured. Without those infos we can't really say whether it's X or Y fault like it's being supposed.

ch9hn commented 3 years ago

We used for the test Puppeteer v8.0.0 with Chromum r856583. Chromium was started with the following args: "--use-fake-ui-for-media-stream", "--use-fake-device-for-media-stream", "--use-file-for-fake-video-capture=exampleclip.y4m", Pagination was configured and we got around 10 - 20 tabs.

prlanzarin commented 3 years ago

Unrelated note but I'd recommend running the headless instances without the fake video file (prefer the built in stream, should be less expensive at the client side).

Anyways, we still need the logs if possible, please (or a confirmation that you can't share them even if it's a testing session). There's really a myriad of reasons webcams might get ejected, and they for sure aren't random.

ch9hn commented 3 years ago

So i got some logfiles with new errors and dropping cams:

The original issue with the core error message is this:
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0126] DEBUG: clientLogger: Initial connection status change. status: connecting, connected: false https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1090450
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0201] DEBUG: clientLogger: Initial connection status change. status: connected, connected: true https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1090450
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0202]  INFO: clientLogger: Connection to Meteor took 0.08s https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1090612
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0225]  INFO: clientLogger: Log information about the client n (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1091783)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0226]  INFO: clientLogger: User successfully went through main.joinRouteHandler fetchToken (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1092852)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0273]  INFO: clientLogger: initCursorStreamListener called u (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1063660)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0274]  INFO: clientLogger: initAnnotationsStreamListener called S (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:687735)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0613]  INFO: clientLogger: Client loaded successfully G.componentDidMount (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1034301)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0614]  INFO: clientLogger: Subscriptions are ready q.componentDidUpdate (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1322311)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0712] DEBUG: clientLogger: Attaching handlers for cursor stream https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1064075
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:43:0713] DEBUG: clientLogger: Attaching handlers for annotations stream https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:688123
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:45:0185] DEBUG: clientLogger: Enumerate devices came back. There are 7 devices and 1 are video inputs https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:1219636
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:47:0352]  INFO: clientLogger: Camera offer generated. Role: share WebRtcPeerSendonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:47:0356]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:50:0191]  INFO: clientLogger: Multiple video provider websocket connection opened. S.onWsOpen (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:557028)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:50:0232] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:50:0238] DEBUG: clientLogger: Camera start request accepted by SFU. Role: share S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:51:0333]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:51:0939]  INFO: clientLogger: Camera media is flowing (server). Role: share S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:53:0420]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:53:0455] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:54:0942]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:59:0053]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:25:59:0109] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:00:0178]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:05:0146]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:05:0217] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:06:0272]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:09:0372]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:09:0464] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:10:0507]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:14:0875]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:14:0947] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:16:0389]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:22:0923]  INFO: clientLogger: Bitrate changed: 100 https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:578500
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:22:0925]  INFO: clientLogger: New camera profile applied: low-u8 https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:579465
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:22:0943]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:23:0044] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:24:0397]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:29:0111]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:29:0235] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:30:0812]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:40:0673]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:41:0330] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:44:0392]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:45:0483]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:45:0679] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:47:0044]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:53:0352]  INFO: clientLogger: Bitrate changed: 90 https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:578500
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:53:0353]  INFO: clientLogger: New camera profile applied: low-u12 https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:579465
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:53:0360]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:53:0523] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:26:54:0524]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:27:20:0225]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:27:20:0350] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:27:21:0563]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:27:33:0478]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:27:34:0704] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:27:39:0443]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:15:0825]  INFO: clientLogger: Camera feed stop requested. Role viewer, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:16:0232]  INFO: clientLogger: Camera feed stop requested. Role viewer, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:16:0962]  INFO: clientLogger: Received request from SFU to stop camera. Role: share S.handlePlayStop (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565258)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:16:0964]  INFO: clientLogger: Camera feed stop requested. Role share, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:17:0557]  INFO: clientLogger: Camera feed stop requested. Role viewer, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:17:0568]  INFO: clientLogger: Camera feed stop requested. Role share, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:17:0762]  INFO: clientLogger: Camera feed stop requested. Role viewer, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:17:0765]  INFO: clientLogger: Camera feed stop requested. Role viewer, restarting false S.stopWebRTCPeer (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:560021)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 Uncaught (in promise) TypeError: Cannot set property 'started' of undefined
    at WebRtcPeerSendonly.<anonymous> (6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331)
    at 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:1
(anonymous) @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
(anonymous) @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:1
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:28:0157]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:28:0371] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:29:0387]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:15:43:0215]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://bm23.inco.video/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:15:43:0283] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://bm23.inco.video/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:15:44:0353]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://bm23.inco.video/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:15:51:0020]  INFO: clientLogger: Camera offer generated. Role: viewer WebRtcPeerRecvonly.<anonymous> (https://bm23.inco.video/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:561872)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:15:51:0655] DEBUG: clientLogger: Camera start request accepted by SFU. Role: viewer S.startResponse (https://bm23.inco.video/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:558700)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:15:54:0532]  INFO: clientLogger: Camera media is flowing (server). Role: viewer S.handlePlayStart (https://bm23.inco.video/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565498)
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
setInterval (async)
ws.onopen @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331 WebSocket is already in CLOSING or CLOSED state.
sendMessage @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
ping @ 6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331
prlanzarin commented 3 years ago

Please attach full server side logs (/var/log/syslog, /var/log/bbb-webrtc-sfu/, /var/log/kurento-media-server/, /var/log/bbb-apps/akka/, /var/log/nginx/html5-client.log [if this one existis]) for a day where you could reproduce the issue.

If you're in the position to send those, put them in a tarball in their full. Do not crop them in any form.

Sorry if I'm being picky/annoying. But cropped logs rarely help. If you can't share full logs, just let me know so that I can at least stop asking for them.

Anyways:

6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:123 [00:28:16:0962] INFO: clientLogger: Received request from SFU to stop camera. Role: share S.handlePlayStop (https://XX.XX.TLD/html5client/6c3e925c964755040758bdd12f06b4f7bd8007ff.js?meteor_js_resource=true:331:565258)

That usually means media stopped flowing through the server and the automated server side ejection (15-30s timer) kicked in and ejected the camera stream.

If that's the case, usually happens when you're putting too much strain over a single test instance/single Chromium. Have in mind that a test machine running 20 tabs won't necessarily perform as expected even if there's CPU/bandwidth available due to bottlenecks which you might or might not expect in the browser. eg.: some specific cameras bork after you do 4 concurrent getUserMedia in a Chrome instance and the browser just stops generating encoded frames.

If you can't share more logs, then consider the possibility I've mentioned ^. Instead of running two dozen bots in a single Chromium process in the same machine, try the following: spin 20 bot instances in 4 smaller machines, 5 per Chromium process, 1 per tab; see if the same thing happens. And please use the built in test stream from Chromium, not the raw y4m.