l7mp/stunner

help - intermitent failures connecting to workers on `cloudretro` example on AWS + EKS + ALB

calexandre opened this issue · 16 comments

I've been building the cloudretro example for a while on multiple kubernetes distributions without issues!
Now I'm trying to run this example on AWS setup (EKS + Fargate + ALB) and I'm getting some intermitent errors:

  • Sometimes I'm able to connect to the workers, and other times I have timeouts
  • I suspect it has something to do with the ICE candidates that are reported on the application - I've posted evidences below on the differences

Versions:

  • I'm using both stunner and stunner-gateway-operator versions 0.16.0 (chart and app)
  • EKS 1.27

Based on the information below, what is the culprit here?
Is there anything I can tweak server side to facilitate this discovery and ensure a successful connection on first attempt?

error attempt

The following errors were captured on the browser using hte Developer tools.

  • Usually when I first reach the coordinator, I usually get the error [rtcp] ice gathering was aborted due to timeout 2000ms.
  • I notice that only one user candidate 02895ab7-03e2-4f4a-9afe-daa99822e2d5.local gets reported and its not reachable (and should not be!)

Error console:

keyboard.js?v=5:128 [input] keyboard has been initialized
joystick.js?v=3:275 [input] joystick has been initialized
touch.js?v=3:304 [input] touch input has been initialized
socket.js?v=4:36 [ws] connecting to wss://home.company.com/ws?room_id=&zone=
socket.js?v=4:42 [ws] <- open connection
socket.js?v=4:43 [ws] -> setting ping interval to 2000ms
controller.js?v=8:79 [ping] <-> {http://worker.company.com:9000/echo: 9999}
rtcp.js?v=4:17 [rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}]
rtcp.js?v=4:106 [rtcp] ice gathering
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: checking
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:1680066927 1 udp 2113937151 02895ab7-03e2-4f4a-9afe-daa99822e2d5.local 54853 typ host generation 0 ufrag rj2C network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"rj2C"}
rtcp.js?v=4:108 [rtcp] ice gathering was aborted due to timeout 2000ms

success attempt

After a couple of retries, we finally have success:

  • Notice that now there are 3 user candidates, one of them is reachable (the one with the public IP)
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:2537811000 1 udp 2113937151 5774c39d-3ada-44b9-b95f-89a858000ac4.local 54903 typ host generation 0 ufrag sRpm network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"sRpm"}
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3567609059 1 udp 1677729535 89.180.168.100 42221 typ srflx raddr 0.0.0.0 rport 0 generation 0 ufrag sRpm network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"sRpm"}
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:4028349664 1 udp 33562623 10.0.22.42 35233 typ relay raddr 

Full log of the success connection:

keyboard.js?v=5:128 [input] keyboard has been initialized
joystick.js?v=3:275 [input] joystick has been initialized
touch.js?v=3:304 [input] touch input has been initialized
socket.js?v=4:36 [ws] connecting to wss://home.company.com/ws?room_id=&zone=
socket.js?v=4:42 [ws] <- open connection
socket.js?v=4:43 [ws] -> setting ping interval to 2000ms
controller.js?v=8:79 [ping] <-> {http://worker.company.com:9000/echo: 9999}
rtcp.js?v=4:17 [rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}]
rtcp.js?v=4:106 [rtcp] ice gathering
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: checking
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:2537811000 1 udp 2113937151 5774c39d-3ada-44b9-b95f-89a858000ac4.local 54903 typ host generation 0 ufrag sRpm network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"sRpm"}
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3567609059 1 udp 1677729535 89.180.168.100 42221 typ srflx raddr 0.0.0.0 rport 0 generation 0 ufrag sRpm network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"sRpm"}
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:4028349664 1 udp 33562623 10.0.22.42 35233 typ relay raddr 89.180.168.178 rport 42221 generation 0 ufrag sRpm network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"sRpm"}
rtcp.js?v=4:113 [rtcp] ice gathering completed
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: connected
rtcp.js?v=4:123 [rtcp] connected...

I appreciate any help on this matter!

rg0now commented

Hello there,

The really first thing that comes to my mind, that this specific part (collecting ICE candidates) happens clientside, and there were many known bugs about chromium sometimes taking MUCH longer to gather candidates.

Before I get deeper, could you please confirm that the same issue happens from other clients/different browsers?

O confirmed it is happening on:

  • edge
  • chrome

I've tried multiple times on firefox and was not able to reproduce the issue (it always works).

Based on this, I think your assumption regarding chromium based browsers might be true...

O confirmed it is happening on:

  • edge
  • chrome

I've tried multiple times on firefox and was not able to reproduce the issue (it always works).

Based on this, I think your assumption regarding chromium based browsers might be true...

Scratch this...
I was able to reproduce this on firefox aswell..But note that it only started happening after a couple of tries..

Here's the full console log:

[ws] closed (1001) socket.js:48:39
This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”.
home.company.com
[state] ??? -> eden [???] controller.js:58:17
[input] keyboard has been initialized keyboard.js:128:17
[input] joystick has been initialized joystick.js:275:17
[input] touch input has been initialized touch.js:304:17
[ws] connecting to wss://home.company.com/ws?room_id=&zone= socket.js:36:17
[ws] <- open connection socket.js:42:17
[ws] -> setting ping interval to 2000ms socket.js:43:17
[ws] <- message 'checkLatency'  
Object { id: "checkLatency", data: "http://worker.company.com:9000/echo", room_id: "", player_index: 0, packet_id: "7e7ef740-8ef2-43b9-997b-d71530623fc1", session_id: "" }
socket.js:54:46
Blocked loading mixed active content “http://worker.company.com:9000/echo?_=1696859302849”
ajax.js:15:17
[ping] <-> 
Object { "http://worker.company.com:9000/echo": 9999 }
controller.js:79:13
[ws] <- message 'init'  
Object { id: "init", data: '["ckhg1f4ednjdhmkl6vgg","[{\\"urls\\":\\"turn:udp.company.com:3478\\",\\"username\\":\\"user-1\\",\\"credential\\":\\"fQvzu2pFOBxtW5Al\\"}]","Double Dragon V - The Shadow Falls","Mortal Kombat","Puzzle Bobble","R-Type III - The Third Lightning","Samurai Shodown","Super Mario All-Stars","Super Mario Bros. 2","Tetris Attack","Super Bomberman","Super Mario Bros. 3","contra","spang","Street Fighter 3","Street Fighter Alpha 2","Super Mario Bros","Super Mario Kart","z(GBA) Mario Kart Super Circuit"]', room_id: "", player_index: 0, packet_id: "ad411c42-1eed-4a7d-9624-fd4a76b5bd0c", session_id: "" }
socket.js:54:46
[rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}] rtcp.js:17:13
[ws] <- message 'offer'  
Object { id: "offer", data: "eyJ0eXBlIjoib2ZmZXIiLCJzZHAiOiJ2PTBcclxubz0tIDY5NzAxOTAzMDIwNDYxNDA4MjkgMTY5Njg1OTMwNCBJTiBJUDQgMC4wLjAuMFxyXG5zPS1cclxudD0wIDBcclxuYT1maW5nZXJwcmludDpzaGEtMjU2IEY3OkNDOkMyOjJFOjY1OkRGOjcwOjcwOkE4OjlCOjQxOkMwOjEzOjIzOjRDOjRBOjZGOkUyOjcwOjI1OkFCOjBBOjBCOkNGOjc4OjQzOkM0OkNGOjBEOjdFOjI1OjcwXHJcbmE9Z3JvdXA6QlVORExFIDAgMSAyXHJcbm09dmlkZW8gOSBVRFAvVExTL1JUUC9TQVZQRiA5NiA5NyA5OCA5OSAxMDAgMTAxIDEwMiAxMjEgMTI3IDEyMCAxMjUgMTA3IDEwOCAxMDkgMTIzIDExOCAxMTZcclxuYz1JTiBJUDQgMC4wLjAuMFxyXG5hPXNldHVwOmFjdHBhc3NcclxuYT1taWQ6MFxyXG5hPWljZS11ZnJhZzpydWZsQ3prbENmWE5nSVJJXHJcbmE9aWNlLXB3ZDpxYXZqQXdvSkxSWWtZbHl6VUVOWHFMcUV2aU1ad1lBVFxyXG5hPXJ0Y3AtbXV4XHJcbmE9cnRjcC1yc2l6ZVxyXG5hPXJ0cG1hcDo5NiBWUDgvOTAwMDBcclxuYT1ydGNwLWZiOjk2IGdvb2ctcmVtYiBcclxuYT1ydGNwLWZiOjk2IGNjbSBmaXJcclxuYT1ydGNwLWZiOjk2IG5hY2sgXHJcbmE9cnRjcC1mYjo5NiBuYWNrIHBsaVxyXG5hPXJ0cG1hcDo5NyBydHgvOTAwMDBcclxuYT1mbXRwOjk3IGFwdD05NlxyXG5hPXJ0cG1hcDo5OCBWUDkvOTAwMDBcclxuYT1mbXRwOjk4IHByb2ZpbGUtaWQ9MFxyXG5hPXJ0Y3AtZmI6OTggZ29vZy1yZW1iIFxyXG5hPXJ0Y3AtZmI6OTggY2NtIGZpclxyXG5hPXJ0Y3AtZmI6OTggbmFjayBcclxuYT1ydGNwLWZiOjk4IG5hY2sgcGxpXHJcbmE9cnRwbWFwOjk5IHJ0eC85MDAwMFxyXG5hPWZtdHA6OTkgYXB0PTk4XHJcbmE9cnRwbWFwOjEwMCBWUDkvOTAwMDBcclxuYT1mbXRwOjEwMCBwcm9maWxlLWlkPTFcclxuYT1ydGNwLWZiOjEwMCBnb29nLXJlbWIgXHJcbmE9cnRjcC1mYjoxMDAgY2NtIGZpclxyXG5hPXJ0Y3AtZmI6MTAwIG5hY2sgXHJcbmE9cnRjcC1mYjoxMDAgbmFjayBwbGlcclxuYT1ydHBtYXA6MTAxIHJ0eC85MDAwMFxyXG5hPWZtdHA6MTAxIGFwdD0xMDBcclxuYT1ydHBtYXA6MTAyIEgyNjQvOTAwMDBcclxuYT1mbXRwOjEwMiBsZXZlbC1hc3ltbWV0cnktYWxsb3dlZD0xO3BhY2tldGl6YXRpb24tbW9kZT0xO3Byb2ZpbGUtbGV2ZWwtaWQ9NDIwMDFmXHJcbmE9cnRjcC1mYjoxMDIgZ29vZy1yZW1iIFxyXG5hPXJ0Y3AtZmI6MTAyIGNjbSBmaXJcclxuYT1ydGNwLWZiOjEwMiBuYWNrIFxyXG5hPXJ0Y3AtZmI6MTAyIG5hY2sgcGxpXHJcbmE9cnRwbWFwOjEyMSBydHgvOTAwMDBcclxuYT1mbXRwOjEyMSBhcHQ9MTAyXHJcbmE9cnRwbWFwOjEyNyBIMjY0LzkwMDAwXHJcbmE9Zm10cDoxMjcgbGV2ZWwtYXN5bW1ldHJ5LWFsbG93ZWQ9MTtwYWNrZXRpemF0aW9uLW1vZGU9MDtwcm9maWxlLWxldmVsLWlkPTQyMDAxZlxyXG5hPXJ0Y3AtZmI6MTI3IGdvb2ctcmVtYiBcclxuYT1ydGNwLWZiOjEyNyBjY20gZmlyXHJcbmE9cnRjcC1mYjoxMjcgbmFjayBcclxuYT1ydGNwLWZiOjEyNyBuYWNrIHBsaVxyXG5hPXJ0cG1hcDoxMjAgcnR4LzkwMDAwXHJcbmE9Zm10cDoxMjAgYXB0PTEyN1xyXG5hPXJ0cG1hcDoxMjUgSDI2NC85MDAwMFxyXG5hPWZtdHA6MTI1IGxldmVsLWFzeW1tZXRyeS1hbGxvd2VkPTE7cGFja2V0aXphdGlvbi1tb2RlPTE7cHJvZmlsZS1sZXZlbC1pZD00MmUwMWZcclxuYT1ydGNwLWZiOjEyNSBnb29nLXJlbWIgXHJcbmE9cnRjcC1mYjoxMjUgY2NtIGZpclxyXG5hPXJ0Y3AtZmI6MTI1IG5hY2sgXHJcbmE9cnRjcC1mYjoxMjUgbmFjayBwbGlcclxuYT1ydHBtYXA6MTA3IHJ0eC85MDAwMFxyXG5hPWZtdHA6MTA3IGFwdD0xMjVcclxuYT1ydHBtYXA6MTA4IEgyNjQvOTAwMDBcclxuYT1mbXRwOjEwOCBsZXZlbC1hc3ltbWV0cnktYWxsb3dlZD0xO3BhY2tldGl6YXRpb24tbW9kZT0wO3Byb2ZpbGUtbGV2ZWwtaWQ9NDJlMDFmXHJcbmE9cnRjcC1mYjoxMDggZ29vZy1yZW1iIFxyXG5hPXJ0Y3AtZmI6MTA4IGNjbSBmaXJcclxuYT1ydGNwLWZiOjEwOCBuYWNrIFxyXG5hPXJ0Y3AtZmI6MTA4IG5hY2sgcGxpXHJcbmE9cnRwbWFwOjEwOSBydHgvOTAwMDBcclxuYT1mbXRwOjEwOSBhcHQ9MTA4XHJcbmE9cnRwbWFwOjEyMyBIMjY0LzkwMDAwXHJcbmE9Zm10cDoxMjMgbGV2ZWwtYXN5bW1ldHJ5LWFsbG93ZWQ9MTtwYWNrZXRpemF0aW9uLW1vZGU9MTtwcm9maWxlLWxldmVsLWlkPTY0MDAzMlxyXG5hPXJ0Y3AtZmI6MTIzIGdvb2ctcmVtYiBcclxuYT1ydGNwLWZiOjEyMyBjY20gZmlyXHJcbmE9cnRjcC1mYjoxMjMgbmFjayBcclxuYT1ydGNwLWZiOjEyMyBuYWNrIHBsaVxyXG5hPXJ0cG1hcDoxMTggcnR4LzkwMDAwXHJcbmE9Zm10cDoxMTggYXB0PTEyM1xyXG5hPXJ0cG1hcDoxMTYgdWxwZmVjLzkwMDAwXHJcbmE9c3NyYzo2MjQwNTQzOSBjbmFtZTpnYW1lLXZpZGVvXHJcbmE9c3NyYzo2MjQwNTQzOSBtc2lkOmdhbWUtdmlkZW8gdmlkZW9cclxuYT1zc3JjOjYyNDA1NDM5IG1zbGFiZWw6Z2FtZS12aWRlb1xyXG5hPXNzcmM6NjI0MDU0MzkgbGFiZWw6dmlkZW9cclxuYT1tc2lkOmdhbWUtdmlkZW8gdmlkZW9cclxuYT1zZW5kcmVjdlxyXG5tPWF1ZGlvIDkgVURQL1RMUy9SVFAvU0FWUEYgMTExIDkgMCA4XHJcbmM9SU4gSVA0IDAuMC4wLjBcclxuYT1zZXR1cDphY3RwYXNzXHJcbmE9bWlkOjFcclxuYT1pY2UtdWZyYWc6cnVmbEN6a2xDZlhOZ0lSSVxyXG5hPWljZS1wd2Q6cWF2akF3b0pMUllrWWx5elVFTlhxTHFFdmlNWndZQVRcclxuYT1ydGNwLW11eFxyXG5hPXJ0Y3AtcnNpemVcclxuYT1ydHBtYXA6MTExIG9wdXMvNDgwMDAvMlxyXG5hPWZtdHA6MTExIG1pbnB0aW1lPTEwO3VzZWluYmFuZGZlYz0xXHJcbmE9cnRwbWFwOjkgRzcyMi84MDAwXHJcbmE9cnRwbWFwOjAgUENNVS84MDAwXHJcbmE9cnRwbWFwOjggUENNQS84MDAwXHJcbmE9c3NyYzo2MzAyNjg5MTIgY25hbWU6Z2FtZS1hdWRpb1xyXG5hPXNzcmM6NjMwMjY4OTEyIG1zaWQ6Z2FtZS1hdWRpbyBhdWRpb1xyXG5hPXNzcmM6NjMwMjY4OTEyIG1zbGFiZWw6Z2FtZS1hdWRpb1xyXG5hPXNzcmM6NjMwMjY4OTEyIGxhYmVsOmF1ZGlvXHJcbmE9bXNpZDpnYW1lLWF1ZGlvIGF1ZGlvXHJcbmE9c2VuZHJlY3ZcclxubT1hcHBsaWNhdGlvbiA5IFVEUC9EVExTL1NDVFAgd2VicnRjLWRhdGFjaGFubmVsXHJcbmM9SU4gSVA0IDAuMC4wLjBcclxuYT1zZXR1cDphY3RwYXNzXHJcbmE9bWlkOjJcclxuYT1zZW5kcmVjdlxyXG5hPXNjdHAtcG9ydDo1MDAwXHJcbmE9aWNlLXVmcmFnOnJ1ZmxDemtsQ2ZYTmdJUklcclxuYT1pY2UtcHdkOnFhdmpBd29KTFJZa1lseXpVRU5YcUxxRXZpTVp3WUFUXHJcbiJ9", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message 'ice_candidate'  
Object { id: "ice_candidate", data: "eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MjEyODg1ODE2NiAxIHVkcCAyMTMwNzA2NDMxIDEwLjAuMzAuMjAyIDU2NjE1IHR5cCBob3N0Iiwic2RwTWlkIjoiIiwic2RwTUxpbmVJbmRleCI6MCwidXNlcm5hbWVGcmFnbWVudCI6bnVsbH0=", room_id: "", player_index: 0, packet_id: "5dcf55a5-7f9b-435f-9a13-06d8dc05db5d", session_id: "" }
socket.js:54:46
Local SDP:  
Object { type: "answer", sdp: "v=0\r\no=mozilla...THIS_IS_SDPARTA-99.0 7013155660875366350 0 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=fingerprint:sha-256 6C:D0:F6:CF:E5:6A:40:B1:3D:98:D1:8F:A5:C2:32:B1:F3:33:9E:B2:7E:D6:0D:FF:E9:14:B7:B3:0E:52:59:8C\r\na=group:BUNDLE 0 1 2\r\na=ice-options:trickle\r\na=msid-semantic:WMS *\r\nm=video 9 UDP/TLS/RTP/SAVPF 96 97 98 99 125 107 108 109\r\nc=IN IP4 0.0.0.0\r\na=recvonly\r\na=fmtp:125 profile-level-id=42e01f;level-asymmetry-allowed=1;packetization-mode=1\r\na=fmtp:108 profile-level-id=42e01f;level-asymmetry-allowed=1\r\na=fmtp:96 max-fs=12288;max-fr=60\r\na=fmtp:97 apt=96\r\na=fmtp:98 max-fs=12288;max-fr=60\r\na=fmtp:99 apt=98\r\na=fmtp:107 apt=125\r\na=fmtp:109 apt=108\r\na=ice-pwd:afa5458636766bd835c2d1b638c79c8b\r\na=ice-ufrag:ce1096c4\r\na=mid:0\r\na=rtcp-fb:96 nack\r\na=rtcp-fb:96 nack pli\r\na=rtcp-fb:96 ccm fir\r\na=rtcp-fb:96 goog-remb\r\na=rtcp-fb:98 nack\r\na=rtcp-fb:98 nack pli\r\na=rtcp-fb:98 ccm fir\r\na=rtcp-fb:98 goog-remb\r\na=rtcp-fb:125 nack\r\na=rtcp-fb:125 nack pli\r\na=rtcp-fb:125 ccm fir\r\na=rtcp-fb:125 goog-remb\r\na=rtcp-fb:108 nack\r\na=rtcp-fb:108 nack pli\r\na=rtcp-fb:108 ccm fir\r\na=rtcp-fb:108 goog-remb\r\na=rtcp-mux\r\na=rtcp-rsize\r\na=rtpmap:96 VP8/90000\r\na=rtpmap:97 rtx/90000\r\na=rtpmap:98 VP9/90000\r\na=rtpmap:99 rtx/90000\r\na=rtpmap:125 H264/90000\r\na=rtpmap:107 rtx/90000\r\na=rtpmap:108 H264/90000\r\na=rtpmap:109 rtx/90000\r\na=setup:active\r\na=ssrc:4026016434 cname:{60341e05-35e8-43d8-9f93-b146d1dced11}\r\nm=audio 9 UDP/TLS/RTP/SAVPF 111 9 0 8\r\nc=IN IP4 0.0.0.0\r\na=recvonly\r\na=fmtp:111 maxplaybackrate=48000;stereo=1;useinbandfec=1;stereo=1\r\na=ice-pwd:afa5458636766bd835c2d1b638c79c8b\r\na=ice-ufrag:ce1096c4\r\na=mid:1\r\na=rtcp-mux\r\na=rtpmap:111 opus/48000/2\r\na=rtpmap:9 G722/8000/1\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=setup:active\r\na=ssrc:2020686424 cname:{60341e05-35e8-43d8-9f93-b146d1dced11}\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 0.0.0.0\r\na=sendrecv\r\na=ice-pwd:afa5458636766bd835c2d1b638c79c8b\r\na=ice-ufrag:ce1096c4\r\na=mid:2\r\na=setup:active\r\na=sctp-port:5000\r\na=max-message-size:1073741823\r\n" }
rtcp.js:157:17
[rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 56615 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null} rtcp.js:179:21
[rtcp] ice gathering rtcp.js:106:29
[rtcp] user candidate: {"candidate":"candidate:0 1 UDP 2122252543 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 62536 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ce1096c4"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:3 1 TCP 2105524479 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ce1096c4"} rtcp.js:100:21
[rtcp] <- iceConnectionState: checking rtcp.js:120:21
[ws] <- message 'ice_candidate'  
Object { id: "ice_candidate", data: "", room_id: "", player_index: 0, packet_id: "1b32ab52-1ee4-4319-8d68-50cc5c953233", session_id: "" }
socket.js:54:46
[rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 56615 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null} rtcp.js:179:21
[ws] <- message 'ice_candidate'  
Object { id: "ice_candidate", data: "eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6NTc3MDM2MDMwIDEgdWRwIDE2OTQ0OTg4MTUgMTguMTAwLjE4Ni4xMzcgMTg2NDMgdHlwIHNyZmx4IHJhZGRyIDAuMC4wLjAgcnBvcnQgNTI1MTAiLCJzZHBNaWQiOiIiLCJzZHBNTGluZUluZGV4IjowLCJ1c2VybmFtZUZyYWdtZW50IjpudWxsfQ==", room_id: "", player_index: 0, packet_id: "c738e2da-1c4f-4386-90c1-1714a43c64a6", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[rtcp] ice gathering was aborted due to timeout 2000ms rtcp.js:108:33
[rtcp] user candidate: {"candidate":"","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"ce1096c4"} rtcp.js:100:21
[rtcp] ice gathering completed rtcp.js:113:29
WebRTC: ICE failed, your TURN server appears to be broken, see about:webrtc for more details
[rtcp] <- iceConnectionState: failed rtcp.js:120:21
[rtcp] connection failed, retry... rtcp.js:134:29
[rtcp] ice gathering rtcp.js:106:29
[rtcp] user candidate: {"candidate":"candidate:0 1 UDP 2122252543 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 56612 typ host","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:3 1 TCP 2105524479 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 9 typ host tcptype active","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:0 1 UDP 2122252543 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 56613 typ host","sdpMid":"1","sdpMLineIndex":1,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:3 1 TCP 2105524479 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 9 typ host tcptype active","sdpMid":"1","sdpMLineIndex":1,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:0 2 UDP 2122252542 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 56614 typ host","sdpMid":"1","sdpMLineIndex":1,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:3 2 TCP 2105524478 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 9 typ host tcptype active","sdpMid":"1","sdpMLineIndex":1,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:0 1 UDP 2122252543 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 56615 typ host","sdpMid":"2","sdpMLineIndex":2,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"candidate:3 1 TCP 2105524479 126e56b6-bc35-4093-ba9f-9a38c8379d55.local 9 typ host tcptype active","sdpMid":"2","sdpMLineIndex":2,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[ws] <- message ''  
Object { id: "", data: "", room_id: "", player_index: 0, packet_id: "", session_id: "" }
socket.js:54:46
[rtcp] ice gathering was aborted due to timeout 2000ms rtcp.js:108:33
[rtcp] user candidate: {"candidate":"","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"","sdpMid":"1","sdpMLineIndex":1,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] user candidate: {"candidate":"","sdpMid":"2","sdpMLineIndex":2,"usernameFragment":"1129d5cc"} rtcp.js:100:21
[rtcp] ice gathering completed rtcp.js:113:29

Any hints?

rg0now commented

Do you think you can gather the corresponding logs from STUNner, preferably at a higher loglevel (say, all:TRACE)? I'm not at all saying that this is not a STUNner bug, but (to my surprise) we see very few similar annoying browser compatibility issues with the other demos...

Sure!

I managed activate verbose mode on the client console. I also persisted the logs over the multiple retries so that you can have a proper timeline.

Console logs captured on Chrome

 [rtcp] <- iceConnectionState: disconnected
 [rtcp] disconnected...
 [ws] ping has been disabled
 [rtcp] WebRTC has been closed
Navigated to https://home.company.com/?id=
inject.js:426 [yoroi/prod] checking if should inject dapp-connector api
inject.js:429 [yoroi/prod] injecting over 'nothing'
inject.js:402 [yoroi/prod] dapp-connector is successfully injected into home.company.com
controller.js?v=8:58 [state] ??? -> eden [???]
keyboard.js?v=5:128 [input] keyboard has been initialized
joystick.js?v=3:275 [input] joystick has been initialized
touch.js?v=3:304 [input] touch input has been initialized
socket.js?v=4:36 [ws] connecting to wss://home.company.com/ws?room_id=&zone=
socket.js?v=4:42 [ws] <- open connection
socket.js?v=4:43 [ws] -> setting ping interval to 2000ms
socket.js?v=4:54 [ws] <- message 'checkLatency'  {id: 'checkLatency', data: 'http://worker.company.com:9000/echo', room_id: '', player_index: 0, packet_id: 'de95ef9a-fab1-4be7-8a4a-faa2c6db79b5', …}
ajax.js?v=3:15 Mixed Content: The page at 'https://home.company.com/?id=' was loaded over HTTPS, but requested an insecure resource 'http://worker.company.com:9000/echo?_=1696860089121'. This request has been blocked; the content must be served over HTTPS.
(anonymous) @ ajax.js?v=3:15
fetch @ ajax.js?v=3:9
(anonymous) @ workerManager.js?v=1:126
checkLatencies @ workerManager.js?v=1:124
onLatencyCheck @ controller.js?v=8:77
(anonymous) @ event.js?v=6:50
pub @ event.js?v=6:49
conn.onmessage @ socket.js?v=4:87
controller.js?v=8:79 [ping] <-> {http://worker.company.com:9000/echo: 9999}
socket.js?v=4:54 [ws] <- message 'init'  {id: 'init', data: '["ckhg1f4ednjdhmkl6vgg","[{\\"urls\\":\\"turn:udp.clo…-Type III - The Third Lightning","Tetris Attack"]', room_id: '', player_index: 0, packet_id: '845e914c-e862-49b5-91ae-ed2c46843127', …}
rtcp.js?v=4:17 [rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}]
socket.js?v=4:54 [ws] <- message 'offer'  {id: 'offer', data: 'eyJ0eXBlIjoib2ZmZXIiLCJzZHAiOiJ2PTBcclxubz0tIDU0MD…RTENFalVXcHBTUWJ4a0FVSWJkb1hUVWdhUkd6c2hUXHJcbiJ9', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MjEyODg1ODE2NiAxIH…pbmVJbmRleCI6MCwidXNlcm5hbWVGcmFnbWVudCI6bnVsbH0=', room_id: '', player_index: 0, packet_id: 'b2ae01e5-aa15-40ac-8fb4-b9336a35fd08', …}
rtcp.js?v=4:157 Local SDP:  RTCSessionDescription {type: 'answer', sdp: 'v=0\r\no=- 3683385275788177392 2 IN IP4 127.0.0.1\r\ns…4:56\r\na=setup:active\r\na=mid:2\r\na=sctp-port:5000\r\n'}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 46783 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:106 [rtcp] ice gathering
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: checking
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:1599402931 1 udp 2113937151 28bef1d5-2391-4224-a7dd-06c4c2a387d6.local 51157 typ host generation 0 ufrag YyG7 network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"YyG7"}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6NTc3MDM2MDMwIDEgdW…uZUluZGV4IjowLCJ1c2VybmFtZUZyYWdtZW50IjpudWxsfQ==', room_id: '', player_index: 0, packet_id: 'c7dfbccc-66fd-4aa3-9db0-c86b79fe21b6', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: '', room_id: '', player_index: 0, packet_id: '14ed3462-440a-4e9f-9669-7bd8749adabf', …}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 46783 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:577036030 1 udp 1694498815 18.100.186.100 30633 typ srflx raddr 0.0.0.0 rport 43390","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:108 [rtcp] ice gathering was aborted due to timeout 2000ms
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: disconnected
rtcp.js?v=4:128 [rtcp] disconnected...
socket.js?v=4:105 [ws] ping has been disabled
rtcp.js?v=4:88 [rtcp] WebRTC has been closed
Navigated to https://home.company.com/?id=
inject.js:426 [yoroi/prod] checking if should inject dapp-connector api
inject.js:429 [yoroi/prod] injecting over 'nothing'
inject.js:402 [yoroi/prod] dapp-connector is successfully injected into home.company.com
controller.js?v=8:58 [state] ??? -> eden [???]
keyboard.js?v=5:128 [input] keyboard has been initialized
joystick.js?v=3:275 [input] joystick has been initialized
touch.js?v=3:304 [input] touch input has been initialized
socket.js?v=4:36 [ws] connecting to wss://home.company.com/ws?room_id=&zone=
socket.js?v=4:42 [ws] <- open connection
socket.js?v=4:43 [ws] -> setting ping interval to 2000ms
socket.js?v=4:54 [ws] <- message 'checkLatency'  {id: 'checkLatency', data: 'http://worker.company.com:9000/echo', room_id: '', player_index: 0, packet_id: '18d14224-793f-4ecb-8925-e941cc165f80', …}
ajax.js?v=3:15 Mixed Content: The page at 'https://home.company.com/?id=' was loaded over HTTPS, but requested an insecure resource 'http://worker.company.com:9000/echo?_=1696860106095'. This request has been blocked; the content must be served over HTTPS.
(anonymous) @ ajax.js?v=3:15
fetch @ ajax.js?v=3:9
(anonymous) @ workerManager.js?v=1:126
checkLatencies @ workerManager.js?v=1:124
onLatencyCheck @ controller.js?v=8:77
(anonymous) @ event.js?v=6:50
pub @ event.js?v=6:49
conn.onmessage @ socket.js?v=4:87
controller.js?v=8:79 [ping] <-> {http://worker.company.com:9000/echo: 9999}
socket.js?v=4:54 [ws] <- message 'init'  {id: 'init', data: '["ckhg1f4ednjdhmkl6vgg","[{\\"urls\\":\\"turn:udp.clo…omberman","Super Mario Bros. 3","contra","spang"]', room_id: '', player_index: 0, packet_id: 'c51d7216-2505-49aa-8684-2a550571fb7f', …}
rtcp.js?v=4:17 [rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}]
socket.js?v=4:54 [ws] <- message 'offer'  {id: 'offer', data: 'eyJ0eXBlIjoib2ZmZXIiLCJzZHAiOiJ2PTBcclxubz0tIDY4OT…jbE5qeExuWnVSaVZnRlpDRG1EUGpwTkRtTW5wVlZcclxuIn0=', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MjEyODg1ODE2NiAxIH…pbmVJbmRleCI6MCwidXNlcm5hbWVGcmFnbWVudCI6bnVsbH0=', room_id: '', player_index: 0, packet_id: '0992819a-acde-4d0d-a9a5-aef5134eb3ed', …}
rtcp.js?v=4:157 Local SDP:  RTCSessionDescription {type: 'answer', sdp: 'v=0\r\no=- 3158726424831661583 2 IN IP4 127.0.0.1\r\ns…3:45\r\na=setup:active\r\na=mid:2\r\na=sctp-port:5000\r\n'}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 36573 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:106 [rtcp] ice gathering
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: checking
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3333310327 1 udp 2113937151 f4e0b5a3-b385-45d4-b2e6-5c8ee27dcbb6.local 64907 typ host generation 0 ufrag NhTP network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"NhTP"}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6NTc3MDM2MDMwIDEgdW…uZUluZGV4IjowLCJ1c2VybmFtZUZyYWdtZW50IjpudWxsfQ==', room_id: '', player_index: 0, packet_id: '593c6ae3-1690-4ab1-b992-57a3b1e8deec', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: '', room_id: '', player_index: 0, packet_id: '71cdd572-f8cb-437c-ae0b-9850201dd39d', …}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 36573 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:577036030 1 udp 1694498815 18.100.186.100 37217 typ srflx raddr 0.0.0.0 rport 40129","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:108 [rtcp] ice gathering was aborted due to timeout 2000ms
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: disconnected
rtcp.js?v=4:128 [rtcp] disconnected...
 [ws] ping has been disabled
 [rtcp] WebRTC has been closed
Navigated to https://home.company.com/?id=
inject.js:426 [yoroi/prod] checking if should inject dapp-connector api
inject.js:429 [yoroi/prod] injecting over 'nothing'
inject.js:402 [yoroi/prod] dapp-connector is successfully injected into home.company.com
controller.js?v=8:58 [state] ??? -> eden [???]
keyboard.js?v=5:128 [input] keyboard has been initialized
joystick.js?v=3:275 [input] joystick has been initialized
touch.js?v=3:304 [input] touch input has been initialized
socket.js?v=4:36 [ws] connecting to wss://home.company.com/ws?room_id=&zone=
socket.js?v=4:42 [ws] <- open connection
socket.js?v=4:43 [ws] -> setting ping interval to 2000ms
socket.js?v=4:54 [ws] <- message 'checkLatency'  {id: 'checkLatency', data: 'http://worker.company.com:9000/echo', room_id: '', player_index: 0, packet_id: 'c4a16926-7e2c-402c-9ef8-6a1a78328e87', …}
ajax.js?v=3:15 Mixed Content: The page at 'https://home.company.com/?id=' was loaded over HTTPS, but requested an insecure resource 'http://worker.company.com:9000/echo?_=1696860122811'. This request has been blocked; the content must be served over HTTPS.
(anonymous) @ ajax.js?v=3:15
fetch @ ajax.js?v=3:9
(anonymous) @ workerManager.js?v=1:126
checkLatencies @ workerManager.js?v=1:124
onLatencyCheck @ controller.js?v=8:77
(anonymous) @ event.js?v=6:50
pub @ event.js?v=6:49
conn.onmessage @ socket.js?v=4:87
controller.js?v=8:79 [ping] <-> {http://worker.company.com:9000/echo: 9999}
socket.js?v=4:54 [ws] <- message 'init'  {id: 'init', data: '["ckhg1dt6d9aem5dafocg","[{\\"urls\\":\\"turn:udp.clo…omberman","Super Mario Bros. 3","contra","spang"]', room_id: '', player_index: 0, packet_id: '24ada2fd-b6ef-4280-a3ec-c3c4ff8f2a18', …}
rtcp.js?v=4:17 [rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}]
socket.js?v=4:54 [ws] <- message 'offer'  {id: 'offer', data: 'eyJ0eXBlIjoib2ZmZXIiLCJzZHAiOiJ2PTBcclxubz0tIDEzNz…2SWlBU0VnWkhTSFl2dmxGYnVLelZzSlViUUJGckZyXHJcbiJ9', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MTEwMjg0MDg5NiAxIH…uZUluZGV4IjowLCJ1c2VybmFtZUZyYWdtZW50IjpudWxsfQ==', room_id: '', player_index: 0, packet_id: 'dc986b91-7493-4a75-922b-d2b9ab7d1cbd', …}
rtcp.js?v=4:157 Local SDP:  RTCSessionDescription {type: 'answer', sdp: 'v=0\r\no=- 2301040562722756230 2 IN IP4 127.0.0.1\r\ns…6:F2\r\na=setup:active\r\na=mid:2\r\na=sctp-port:5000\r\n'}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:1102840896 1 udp 2130706431 10.0.18.74 48916 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:106 [rtcp] ice gathering
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: checking
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3584442442 1 udp 2113937151 472c9864-3826-4aa7-b8eb-4033e4c0024f.local 52426 typ host generation 0 ufrag jxK8 network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"jxK8"}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: '', room_id: '', player_index: 0, packet_id: '4b4710c1-e8e9-41d5-8835-f474218e9c2c', …}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:1102840896 1 udp 2130706431 10.0.18.74 48916 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6NTc3MDM2MDMwIDEgdW…uZUluZGV4IjowLCJ1c2VybmFtZUZyYWdtZW50IjpudWxsfQ==', room_id: '', player_index: 0, packet_id: '3bb193af-8116-43a4-b823-b016128df35f', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:108 [rtcp] ice gathering was aborted due to timeout 2000ms
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: disconnected
rtcp.js?v=4:128 [rtcp] disconnected...
socket.js?v=4:105 [ws] ping has been disabled
rtcp.js?v=4:88 [rtcp] WebRTC has been closed
Navigated to https://home.company.com/?id=
inject.js:426 [yoroi/prod] checking if should inject dapp-connector api
inject.js:429 [yoroi/prod] injecting over 'nothing'
inject.js:402 [yoroi/prod] dapp-connector is successfully injected into home.company.com
controller.js?v=8:58 [state] ??? -> eden [???]
keyboard.js?v=5:128 [input] keyboard has been initialized
joystick.js?v=3:275 [input] joystick has been initialized
touch.js?v=3:304 [input] touch input has been initialized
socket.js?v=4:36 [ws] connecting to wss://home.company.com/ws?room_id=&zone=
socket.js?v=4:42 [ws] <- open connection
socket.js?v=4:43 [ws] -> setting ping interval to 2000ms
socket.js?v=4:54 [ws] <- message 'checkLatency'  {id: 'checkLatency', data: 'http://worker.company.com:9000/echo', room_id: '', player_index: 0, packet_id: '9d414e91-7f74-419a-9d50-a38192e78cfd', …}
ajax.js?v=3:15 Mixed Content: The page at 'https://home.company.com/?id=' was loaded over HTTPS, but requested an insecure resource 'http://worker.company.com:9000/echo?_=1696860139496'. This request has been blocked; the content must be served over HTTPS.
(anonymous) @ ajax.js?v=3:15
fetch @ ajax.js?v=3:9
(anonymous) @ workerManager.js?v=1:126
checkLatencies @ workerManager.js?v=1:124
onLatencyCheck @ controller.js?v=8:77
(anonymous) @ event.js?v=6:50
pub @ event.js?v=6:49
conn.onmessage @ socket.js?v=4:87
controller.js?v=8:79 [ping] <-> {http://worker.company.com:9000/echo: 9999}
socket.js?v=4:54 [ws] <- message 'init'  {id: 'init', data: '["ckhg1f4ednjdhmkl6vgg","[{\\"urls\\":\\"turn:udp.clo…er Mario Kart","z(GBA) Mario Kart Super Circuit"]', room_id: '', player_index: 0, packet_id: '0f4b31f9-4469-41d2-a1d9-257f35fcfbf8', …}
rtcp.js?v=4:17 [rtcp] <- received coordinator's ICE STUN/TURN config: [{"urls":"turn:udp.company.com:3478","username":"user-1","credential":"fQvzu2pFOBxtW5Al"}]
socket.js?v=4:54 [ws] <- message 'offer'  {id: 'offer', data: 'eyJ0eXBlIjoib2ZmZXIiLCJzZHAiOiJ2PTBcclxubz0tIDY1OT…aUHBLeWpmRkxUclRhbWtzdlBXeXRRWWtFTlFOSFdXXHJcbiJ9', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MjEyODg1ODE2NiAxIH…pbmVJbmRleCI6MCwidXNlcm5hbWVGcmFnbWVudCI6bnVsbH0=', room_id: '', player_index: 0, packet_id: '65d1dfd1-964f-48a7-bf71-a2b38f772dc5', …}
rtcp.js?v=4:157 Local SDP:  RTCSessionDescription {type: 'answer', sdp: 'v=0\r\no=- 5001145989748845065 2 IN IP4 127.0.0.1\r\ns…3:0A\r\na=setup:active\r\na=mid:2\r\na=sctp-port:5000\r\n'}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 35636 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:106 [rtcp] ice gathering
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6NTc3MDM2MDMwIDEgdW…uZUluZGV4IjowLCJ1c2VybmFtZUZyYWdtZW50IjpudWxsfQ==', room_id: '', player_index: 0, packet_id: '2a39812c-0ee2-4751-9fd8-799c2ee5e37e', …}
socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: '', room_id: '', player_index: 0, packet_id: '93fe6b38-ddaf-4dab-815b-91e89e884066', …}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 35636 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:577036030 1 udp 1694498815 18.100.186.100 33520 typ srflx raddr 0.0.0.0 rport 43403","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: checking
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:1108626289 1 udp 2113937151 ede1c2ef-c58e-489a-a4bd-e8c59e2cbbfc.local 62721 typ host generation 0 ufrag evwk network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"evwk"}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3447061017 1 udp 1677729535 89.180.168.100 42127 typ srflx raddr 0.0.0.0 rport 0 generation 0 ufrag evwk network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"evwk"}
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3339608042 1 udp 33562623 10.0.22.42 46610 typ relay raddr 89.180.168.100 rport 42127 generation 0 ufrag evwk network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"evwk"}
rtcp.js?v=4:113 [rtcp] ice gathering completed
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:120 [rtcp] <- iceConnectionState: connected
rtcp.js?v=4:123 [rtcp] connected...
rtcp.js?v=4:29 [rtcp] ondatachannel: game-input
rtcp.js?v=4:32 [rtcp] the input channel has opened
controller.js?v=8:109 [control] loading menu screen
gameList.js?v=3:23 [games] load game menu
controller.js?v=8:58 [state] eden -> menu [eden]

On the stunnerd side,

  • I need instructions on how to change the STUNNER_LOGLEVEL using the helm approach (I only found that for standalone mode)
  • the server only wrote INFO logs when the client successfully connected.
14:41:55.005994 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42163
14:41:55.032751 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42163
14:41:55.032808 handlers.go:84: stunner-auth INFO: permission granted on listener "stunner/udp-gateway/udp-listener" for client "89.180.168.100:42163" to peer 10.0.31.246 via cluster "stunner/cloudretro-media-plane"
14:41:55.032885 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42163
14:41:55.032910 turn.go:239: turn INFO: permission denied for client 89.180.168.100:42163 to peer 18.100.186.100
14:41:55.068289 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42163
14:41:55.068352 handlers.go:84: stunner-auth INFO: permission granted on listener "stunner/udp-gateway/udp-listener" for client "89.180.168.100:42163" to peer 10.0.31.246 via cluster "stunner/cloudretro-media-plane"
14:41:55.100473 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42163
14:41:55.100513 handlers.go:84: stunner-auth INFO: permission granted on listener "stunner/udp-gateway/udp-listener" for client "89.180.168.100:42163" to peer 10.0.31.246 via cluster "stunner/cloudretro-media-plane"

I was able to activate the TRACE logs on stunner.

  • there's no activity whatsoever during the retry attempts, meaning that this is something happening on the client side.

Stunner logs with TRACE enabled:

16:22:00.523813 reconcile.go:95: cluster-manager TRACE: running the new-object job queue
16:22:00.523817 reconcile.go:109: cluster-manager TRACE: running the deletion job queue
16:22:00.523821 reconcile.go:118: cluster-manager TRACE: running the reconciliation job queue
16:22:00.523837 reconcile.go:121: cluster-manager TRACE: reconciling object "stunner/cloudretro-media-plane": "stunner/cloudretro-media-plane":{type="STATIC",protocol="UDP",endpoints=[10.0.18.74,10.0.30.20,172.20.23.5]} -> "stunner/cloudretro-media-plane":{type="STATIC",protocol="UDP",endpoints=[10.0.18.74,10.0.30.202,172.20.23.52]}
16:22:00.523848 cluster.go:75: stunner-cluster-stunner/cloudretro-media-plane TRACE: Reconcile: "stunner/cloudretro-media-plane":{type="STATIC",protocol="UDP",endpoints=[10.0.18.74,10.0.30.202,172.20.23.52]}
16:22:00.523858 reconcile.go:131: cluster-manager DEBUG: reconciliation ready: to-be-created: 0, changed: 1, deleted: 0
16:22:00.523866 reconcile.go:177: stunner INFO: reconciliation ready: new objects: 0, changed objects: 3, deleted objects: 0, started objects: 0, restarted objects: 0
16:22:00.523888 reconcile.go:181: stunner INFO: status: READY, realm: stunner.l7mp.io, authentication: plaintext, listeners: stunner/udp-gateway/udp-listener: [turn-udp://10.0.22.42:3478<32768:65535>], active allocations: 0
16:22:00.523894 main.go:166: stunnerd TRACE: reconciliation ready
16:22:00.523973 client.go:237: config-watcher DEBUG: ignoring recurrent notify event for the same config file
16:24:51.153080 server.go:39: turn DEBUG: Received 20 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.153102 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.153109 stun.go:12: turn DEBUG: Received BindingRequest from 89.180.168.100:42239
16:24:51.153407 server.go:39: turn DEBUG: Received 28 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.153421 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.153429 turn.go:18: turn DEBUG: Received AllocateRequest from 89.180.168.100:42239
16:24:51.178067 server.go:39: turn DEBUG: Received 120 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.178080 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.178089 turn.go:18: turn DEBUG: Received AllocateRequest from 89.180.168.100:42239
16:24:51.178104 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42239
16:24:51.178117 handlers.go:30: stunner-auth DEBUG: plaintext auth request: valid username
16:24:51.178214 allocation_manager.go:116: turn DEBUG: Listening on relay address: 10.0.22.42:34149
16:24:51.203893 server.go:39: turn DEBUG: Received 124 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.203909 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.203919 turn.go:214: turn DEBUG: Received CreatePermission from 89.180.168.100:42239
16:24:51.203938 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42239
16:24:51.203950 handlers.go:30: stunner-auth DEBUG: plaintext auth request: valid username
16:24:51.203970 handlers.go:74: stunner-auth DEBUG: permission handler for listener "stunner/udp-gateway/udp-listener": client "89.180.168.100:42239", peer "10.0.18.74"
16:24:51.203980 handlers.go:79: stunner-auth TRACE: considering route to cluster "stunner/cloudretro-media-plane"
16:24:51.203987 handlers.go:81: stunner-auth TRACE: considering cluster "stunner/cloudretro-media-plane"
16:24:51.203994 cluster.go:189: stunner-cluster-stunner/cloudretro-media-plane TRACE: Route: cluster "stunner/cloudretro-media-plane" of type STATIC, peer IP: 10.0.18.74
16:24:51.204021 cluster.go:196: stunner-cluster-stunner/cloudretro-media-plane TRACE: considering endpoint {"10.0.18.74" "ffffffff"}
16:24:51.204031 handlers.go:84: stunner-auth INFO: permission granted on listener "stunner/udp-gateway/udp-listener" for client "89.180.168.100:42239" to peer 10.0.18.74 via cluster "stunner/cloudretro-media-plane"
16:24:51.204038 turn.go:244: turn DEBUG: Adding permission for 10.0.18.74:56577
16:24:51.206908 allocation.go:246: turn DEBUG: Relay socket 10.0.22.42:34149 received 100 bytes from 10.0.18.74:56577
16:24:51.206936 allocation.go:276: turn DEBUG: Relaying message from 10.0.18.74:56577 to client at 89.180.168.100:42239
16:24:51.206976 allocation.go:246: turn DEBUG: Relay socket 10.0.22.42:34149 received 100 bytes from 10.0.18.74:35833
16:24:51.206988 allocation.go:276: turn DEBUG: Relaying message from 10.0.18.74:35833 to client at 89.180.168.100:42239
16:24:51.231221 server.go:39: turn DEBUG: Received 100 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.231234 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.231240 turn.go:269: turn DEBUG: Received SendIndication from 89.180.168.100:42239
16:24:51.231751 server.go:39: turn DEBUG: Received 124 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.231764 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.231772 turn.go:214: turn DEBUG: Received CreatePermission from 89.180.168.100:42239
16:24:51.231797 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42239
16:24:51.231807 handlers.go:30: stunner-auth DEBUG: plaintext auth request: valid username
16:24:51.231821 handlers.go:74: stunner-auth DEBUG: permission handler for listener "stunner/udp-gateway/udp-listener": client "89.180.168.100:42239", peer "10.0.18.74"
16:24:51.231828 handlers.go:79: stunner-auth TRACE: considering route to cluster "stunner/cloudretro-media-plane"
16:24:51.231835 handlers.go:81: stunner-auth TRACE: considering cluster "stunner/cloudretro-media-plane"
16:24:51.231843 cluster.go:189: stunner-cluster-stunner/cloudretro-media-plane TRACE: Route: cluster "stunner/cloudretro-media-plane" of type STATIC, peer IP: 10.0.18.74
16:24:51.231851 cluster.go:196: stunner-cluster-stunner/cloudretro-media-plane TRACE: considering endpoint {"10.0.18.74" "ffffffff"}
16:24:51.231856 handlers.go:84: stunner-auth INFO: permission granted on listener "stunner/udp-gateway/udp-listener" for client "89.180.168.100:42239" to peer 10.0.18.74 via cluster "stunner/cloudretro-media-plane"
16:24:51.231861 turn.go:244: turn DEBUG: Adding permission for 10.0.18.74:35833
16:24:51.231897 server.go:39: turn DEBUG: Received 100 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.231900 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.231904 turn.go:269: turn DEBUG: Received SendIndication from 89.180.168.100:42239
16:24:51.248099 server.go:39: turn DEBUG: Received 144 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.248112 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.248119 turn.go:269: turn DEBUG: Received SendIndication from 89.180.168.100:42239
16:24:51.248802 allocation.go:246: turn DEBUG: Relay socket 10.0.22.42:34149 received 64 bytes from 10.0.18.74:56577
16:24:51.248824 allocation.go:276: turn DEBUG: Relaying message from 10.0.18.74:56577 to client at 89.180.168.100:42239
16:24:51.273811 server.go:39: turn DEBUG: Received 132 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.273823 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.273830 turn.go:302: turn DEBUG: Received ChannelBindRequest from 89.180.168.100:42239
16:24:51.273846 handlers.go:25: stunner-auth INFO: plaintext auth request: username="user-1" realm="stunner.l7mp.io" srcAddr=89.180.168.100:42239
16:24:51.273857 handlers.go:30: stunner-auth DEBUG: plaintext auth request: valid username
16:24:51.273871 handlers.go:74: stunner-auth DEBUG: permission handler for listener "stunner/udp-gateway/udp-listener": client "89.180.168.100:42239", peer "10.0.18.74"
16:24:51.273881 handlers.go:79: stunner-auth TRACE: considering route to cluster "stunner/cloudretro-media-plane"
16:24:51.273886 handlers.go:81: stunner-auth TRACE: considering cluster "stunner/cloudretro-media-plane"
16:24:51.273894 cluster.go:189: stunner-cluster-stunner/cloudretro-media-plane TRACE: Route: cluster "stunner/cloudretro-media-plane" of type STATIC, peer IP: 10.0.18.74
16:24:51.273903 cluster.go:196: stunner-cluster-stunner/cloudretro-media-plane TRACE: considering endpoint {"10.0.18.74" "ffffffff"}
16:24:51.273914 handlers.go:84: stunner-auth INFO: permission granted on listener "stunner/udp-gateway/udp-listener" for client "89.180.168.100:42239" to peer 10.0.18.74 via cluster "stunner/cloudretro-media-plane"
16:24:51.273924 turn.go:340: turn DEBUG: Binding channel 16384 to 10.0.18.74:56577
16:24:51.273981 server.go:39: turn DEBUG: Received 196 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.273986 server.go:64: turn DEBUG: Handling TURN packet
16:24:51.273994 turn.go:269: turn DEBUG: Received SendIndication from 89.180.168.100:42239
16:24:51.309082 server.go:39: turn DEBUG: Received 112 bytes of udp from 89.180.168.100:42239 on [::]:3478
16:24:51.309104 server.go:49: turn DEBUG: Received DataPacket from 89.180.168.100:42239
16:24:51.309109 turn.go:356: turn DEBUG: Received ChannelData from 89.180.168.100:42239
16:24:51.309982 allocation.go:246: turn DEBUG: Relay socket 10.0.22.42:34149 received 64 bytes from 10.0.18.74:56577
rg0now commented

Thanks a lot, this indeed seems like a client problem. I'm wondering whether the empty messages received from the coordinator may be the origin of the problem:

socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:108 [rtcp] ice gathering was aborted due to timeout 2000ms

I guess the client should receive the ICE candidates from the server in these messages, but for some reason the messages are empty.

That being said, it seems that there actually exists a candidate pair that should work (at least for the 3rd attempt):

socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MjEyODg1ODE2NiAxIH…pbmVJbmRleCI6MCwidXNlcm5hbWVGcmFnbWVudCI6bnVsbH0=', room_id: '', player_index: 0, packet_id: '65d1dfd1-964f-48a7-bf71-a2b38f772dc5', …}
...
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 35636 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
...
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3339608042 1 udp 33562623 10.0.22.42 46610 typ relay raddr 89.180.168.100 rport 42127 generation 0 ufrag evwk network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"evwk"}

I'm wondering why this doesn't work (not sure whether the "usernameFragment":null on the received candidate is an error).

rg0now commented

@bbalint105 let me know if you have time (and motivation) to debug this sometime

Thanks a lot, this indeed seems like a client problem. I'm wondering whether the empty messages received from the coordinator may be the origin of the problem:

socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
socket.js?v=4:54 [ws] <- message ''  {id: '', data: '', room_id: '', player_index: 0, packet_id: '', …}
rtcp.js?v=4:108 [rtcp] ice gathering was aborted due to timeout 2000ms

I guess the client should receive the ICE candidates from the server in these messages, but for some reason the messages are empty.

That being said, it seems that there actually exists a candidate pair that should work (at least for the 3rd attempt):

socket.js?v=4:54 [ws] <- message 'ice_candidate'  {id: 'ice_candidate', data: 'eyJjYW5kaWRhdGUiOiJjYW5kaWRhdGU6MjEyODg1ODE2NiAxIH…pbmVJbmRleCI6MCwidXNlcm5hbWVGcmFnbWVudCI6bnVsbH0=', room_id: '', player_index: 0, packet_id: '65d1dfd1-964f-48a7-bf71-a2b38f772dc5', …}
...
rtcp.js?v=4:179 [rtcp] add candidate: {"candidate":"candidate:2128858166 1 udp 2130706431 10.0.30.202 35636 typ host","sdpMid":"","sdpMLineIndex":0,"usernameFragment":null}
...
rtcp.js?v=4:100 [rtcp] user candidate: {"candidate":"candidate:3339608042 1 udp 33562623 10.0.22.42 46610 typ relay raddr 89.180.168.100 rport 42127 generation 0 ufrag evwk network-cost 999","sdpMid":"0","sdpMLineIndex":0,"usernameFragment":"evwk"}

I'm wondering why this doesn't work (not sure whether the "usernameFragment":null on the received candidate is an error).

Which component responds with the available candidates? Is it the stunnerd workload?

I looked into it, and it could be something with the CloudRetro code.
For first look, it seems like they already fixed it, but the branch I provided is ~170 changes behind, not to talk about they changed the entire handling of ICE servers as well (thus, there would be the need to redo/re-plan the whole demo).

I asked the devs if they know anything about this particular issue, and if it was fixed already.

rg0now commented

Any plans to redo the demo?

If their answer is straightforwward, and I don't have to test and redo everything that would be nice.

Followup:
There were no such issues with CloudRetro so far, so there are some kind of sneaky bugs in-between.

First of all, thank you for debugging the issue @bbalint105

I already tried to debug the client's code, but I have not been able to pinpoint the problem...

Some questions:

  • Were you able to reproduce it on your end?
  • Can you confirm that is something on the client and not on the server side?
  • How is the discovery of ICE candidates performed? I'm trying to understand how those clients in the form <guid>.local appear on the ICE candidates list...

Closing this for now as it seems like a CloudRetro issue. Feel free to reopen if new input becomes available.