search

m1k1o / neko

A self hosted virtual browser that runs in docker and uses WebRTC.
https://neko.m1k1o.net/
Apache License 2.0
5.96k stars 449 forks source link

Can't log back in if all users disconnect and audio device doesn't exist #284

Closed darnfinecoffee closed 9 months ago

darnfinecoffee commented 1 year ago

Hi, Since v2.8, I can't seem to be able to log back in after one (or multiple) users connect, then all log out. The login prompt times out. A restart of the server is needed for it to work again.

For example: user1 logs in -> user1 logs out => timeout when trying to log back in user1 logs in -> user2 logs in -> user2 logs out => can still connect as long as user1 is connected user1 logs in -> user2 logs in -> user2 logs out -> user3 logs in -> user1 logs out => can still connect as long as user3 is connected user1 logs in -> user2 logs in -> user 2 logs out -> user1 logs out => timeout when trying to log in

Everything was working fine with v2.7 using the exact same config.

Logs from 2.8, connecting/disconnecting with one user:

 nurdism/m1k1o server v2.8.0
9:18AM INF preflight complete config=/etc/neko/neko.yaml debug=false logging=false
9:18AM INF starting neko server service=neko
9:18AM INF setting initial screen size module=desktop screen_size=1280x720@30
9:18AM INF using TCP MUX listener=0.0.0.0:60000 module=webrtc
9:18AM INF using UDP MUX module=webrtc port=60000
9:18AM INF webrtc starting ephemeral_port_range=59000-59100 ice_lite=true ice_servers="[{URLs:[stun:stun.l.google.com:19302] Username: Credential:<nil> CredentialType:password}]" module=webrtc nat_ips=[PublicIP]
9:18AM INF Listening TCP on 0.0.0.0:60000 module=webrtc submodule=pion subsystem=ice-tcp
9:18AM WRN http listening on neko.domain:8080 module=http
9:18AM INF neko ready service=neko
9:18AM INF creating pipeline codec=opus module=capture src="pulsesrc device=audio_output.monitor ! audio/x-raw,channels=2 ! audioconvert ! opusenc inband-fec=true bitrate=320000 ! appsink name=appsinkaudio" submodule=stream-sink video_id=audio
9:18AM INF first listener, starting module=capture submodule=stream-sink video_id=audio
9:18AM INF creating pipeline codec=vp8 module=capture src="ximagesrc display-name=:0.0 show-pointer=true use-damage=false ! video/x-raw,framerate=30/1 ! videoconvert ! queue !  vp8enc target-bitrate=1996800 cpu-used=4 end-usage=cbr threads=4 deadline=1 undershoot=95 buffer-size=12288 buffer-initial-size=6144 buffer-optimal-size=9216 keyframe-max-dist=25 min-quantizer=4 max-quantizer=20  ! appsink name=appsinkvideo" submodule=stream-sink video_id=video
9:18AM INF first listener, starting module=capture submodule=stream-sink video_id=video
9:18AM INF signaling state changed to have-local-offer module=webrtc submodule=pion subsystem=pc
9:18AM WRN negotiation is needed module=webrtc
9:18AM ERR creating offer failed error="InvalidModificationError: invalid proposed signaling state transition: have-local-offer->SetLocal(offer)->have-local-offer" module=webrtc
9:18AM INF signal update - LocalCandidate id=Y-mFZcBPkcZTXi55U8F2XBWX4k4XKPWB module=session
9:18AM INF signal update - LocalCandidate id=Y-mFZcBPkcZTXi55U8F2XBWX4k4XKPWB module=session
9:18AM INF sent all ICECandidates module=webrtc
9:18AM INF signal update - RemoteAnswer id=Y-mFZcBPkcZTXi55U8F2XBWX4k4XKPWB module=session
9:18AM INF signaling state changed to stable module=webrtc submodule=pion subsystem=pc
9:18AM INF Setting new connection state: Checking module=webrtc submodule=pion subsystem=ice
9:18AM INF ICE connection state changed: checking module=webrtc submodule=pion subsystem=pc
9:18AM INF connection state has changed connection_state=checking module=webrtc
9:18AM INF Setting new connection state: Connected module=webrtc submodule=pion subsystem=ice
9:18AM INF ICE connection state changed: connected module=webrtc submodule=pion subsystem=pc
9:18AM INF connection state has changed connection_state=connected module=webrtc
9:18AM INF peer connection state changed: connected module=webrtc submodule=pion subsystem=pc
9:18AM INF peer connected id=Y-mFZcBPkcZTXi55U8F2XBWX4k4XKPWB module=webrtc
9:18AM WRN read message error error="websocket: close 1005 (no status)" module=websocket
9:18AM WRN Failed to accept RTP stream is already closed module=webrtc submodule=pion subsystem=pc
9:18AM WRN Failed to read from candidate tcp4 host [PublicIP]:60000: io: read/write on closed pipe module=webrtc submodule=pion subsystem=ice
9:18AM WRN Failed to accept RTCP stream is already closed module=webrtc submodule=pion subsystem=pc
9:18AM INF Setting new connection state: Closed module=webrtc submodule=pion subsystem=ice
9:18AM INF peer connection state changed: closed module=webrtc submodule=pion subsystem=pc
9:18AM INF ICE connection state changed: closed module=webrtc submodule=pion subsystem=pc
9:18AM INF connection state has changed connection_state=closed module=webrtc
9:18AM INF peer closed id=Y-mFZcBPkcZTXi55U8F2XBWX4k4XKPWB module=webrtc

Same thing but on 2.7:

 nurdism/m1k1o server v2.7.0 dev
9:14AM INF preflight complete config=/etc/neko/neko.yaml debug=false logging=false
9:14AM INF starting neko server service=neko
9:14AM INF setting initial screen size module=desktop screen_size=1280x720@30
9:14AM INF using TCP MUX listener=0.0.0.0:60000 module=webrtc
9:14AM WRN UDPMuxDefault should not listening on unspecified address, use NewMultiUDPMuxFromPort instead module=webrtc submodule=pion subsystem=ice-udp
9:14AM INF using UDP MUX listener=0.0.0.0:60000 module=webrtc
9:14AM INF webrtc starting ephemeral_port_range=59000-59100 ice_lite=true ice_servers="[{URLs:[stun:stun.l.google.com:19302] Username: Credential:<nil> CredentialType:password}]" module=webrtc nat_ips=[PublicIP]
9:14AM INF Listening TCP on 0.0.0.0:60000 module=webrtc submodule=pion subsystem=ice-tcp
9:14AM WRN http listening on neko.domain:8080 module=http
9:14AM INF neko ready service=neko
9:15AM INF creating pipeline codec=opus module=capture src="pulsesrc device=auto_null.monitor ! audio/x-raw,channels=2 ! audioconvert ! opusenc inband-fec=true bitrate=320000 ! appsink name=appsink" submodule=stream-sink video_id=audio
9:15AM INF first listener, starting module=capture submodule=stream-sink video_id=audio
9:15AM INF creating pipeline codec=vp8 module=capture src="ximagesrc display-name=:0.0 show-pointer=true use-damage=false ! video/x-raw,framerate=30/1 ! videoconvert ! queue !  vp8enc target-bitrate=1996800 cpu-used=4 end-usage=cbr threads=4 deadline=1 undershoot=95 buffer-size=12288 buffer-initial-size=6144 buffer-optimal-size=9216 keyframe-max-dist=25 min-quantizer=4 max-quantizer=20  ! appsink name=appsink" submodule=stream-sink video_id=video
9:15AM INF first listener, starting module=capture submodule=stream-sink video_id=video
9:15AM INF signaling state changed to have-local-offer module=webrtc submodule=pion subsystem=pc
9:15AM INF sent all ICECandidates module=webrtc
9:15AM INF signal update - RemoteAnswer id=dyUB-wXo35CaQmE1BknxYpFCWAYvvYho module=session
9:15AM INF signaling state changed to stable module=webrtc submodule=pion subsystem=pc
9:15AM INF Setting new connection state: Checking module=webrtc submodule=pion subsystem=ice
9:15AM INF ICE connection state changed: checking module=webrtc submodule=pion subsystem=pc
9:15AM INF connection state has changed connection_state=checking module=webrtc
9:15AM INF Setting new connection state: Connected module=webrtc submodule=pion subsystem=ice
9:15AM INF ICE connection state changed: connected module=webrtc submodule=pion subsystem=pc
9:15AM INF connection state has changed connection_state=connected module=webrtc
9:15AM INF peer connection state changed: connected module=webrtc submodule=pion subsystem=pc
9:15AM INF peer connected id=dyUB-wXo35CaQmE1BknxYpFCWAYvvYho module=webrtc
9:15AM WRN read message error error="websocket: close 1005 (no status)" module=websocket
9:15AM WRN Failed to accept RTP stream is already closed module=webrtc submodule=pion subsystem=pc
9:15AM INF Setting new connection state: Closed module=webrtc submodule=pion subsystem=ice
9:15AM INF peer connection state changed: closed module=webrtc submodule=pion subsystem=pc
9:15AM WRN Failed to accept RTCP stream is already closed module=webrtc submodule=pion subsystem=pc
9:15AM INF ICE connection state changed: closed module=webrtc submodule=pion subsystem=pc
9:15AM INF connection state has changed connection_state=closed module=webrtc
9:15AM INF peer closed id=dyUB-wXo35CaQmE1BknxYpFCWAYvvYho module=webrtc
9:15AM INF destroying pipeline module=capture submodule=stream-sink video_id=audio
9:15AM INF last listener, stopping module=capture submodule=stream-sink video_id=audio
9:15AM INF destroying pipeline module=capture submodule=stream-sink video_id=video
9:15AM INF last listener, stopping module=capture submodule=stream-sink video_id=video
9:15AM INF destroying session module=session session_id=dyUB-wXo35CaQmE1BknxYpFCWAYvvYho

Seems like the only difference is Failed to read from candidate tcp4 host [PublicIP]:60000: io: read/write on closed pipe module=webrtc submodule=pion subsystem=ice, maybe that's related?

My config file:

screen: "1280x720@30"
max_fps: 30
video_codec: "vp8"
video_bitrate: 2000
hwenc: "none"
audio_codec: "opus"
audio_bitrate: 256

password: "password"
password_admin: "admin"

bind: "neko.domain:8080"
udpmux: "60000"
tcpmux: "60000"
nat1to1: "[PublicIP]"
icelite: true

display: ":0.0"
static: "/usr/share/neko/dist"

The same thing happens no matter if I use the udpmux or epr setting. I am running Neko directly on an Alpine v3.17 VM, without docker, with nginx as reverse proxy.

m1k1o commented 1 year ago

I can't seem to replicate this. I also got the same error Failed to read from candidate tcp4 host [PublicIP]:60000: io: read/write on closed pipe module=webrtc submodule=pion subsystem=ice but I was able to log in and log out at any time.

What you describe looks like gstreamer has problems with starting or stopping pipeline. Because pipeline is started when first user joins. When others join meanwhile, it is still running. When the last user leaves, it stops both pipelines (audio and video). It looks like there might be some sort of blocking happening when stopping gstreamer pipeline that subsequently blocks whole server and nobody can join.

Could you try changing screen size? That also restarts gstreamer pipeline. If neko freezes after, then its problem with gstreamer.

Additionally, could you add debug: true to get more info? And with debug mode turn off please try to log in, log out and again log in.

darnfinecoffee commented 1 year ago

Here is the debug log (log in, change screen res to 800*600, change it back to 720, log out, attempt to log in again):

 nurdism/m1k1o server v2.8.0 
11:05AM INF preflight complete config=/etc/neko/neko.yaml debug=true logging=false
11:05AM INF starting neko server service=neko
11:05AM INF setting initial screen size module=desktop screen_size=1280x720@30
11:05AM INF using TCP MUX listener=0.0.0.0:60000 module=webrtc
11:05AM INF using UDP MUX module=webrtc port=60000
11:05AM INF Listening TCP on 0.0.0.0:60000 module=webrtc submodule=pion subsystem=ice-tcp
11:05AM INF webrtc starting ephemeral_port_range=59000-59100 ice_lite=true ice_servers="[{URLs:[stun:stun.l.google.com:19302] Username: Credential:<nil> CredentialType:password}]" module=webrtc nat_ips=[PublicIP]
11:05AM WRN http listening on neko.domain:8080 module=http
11:05AM INF neko ready service=neko
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000001","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48598","scheme":"http","uri":"http://neko.domain/"} res={"bytes":1424,"elapsed":2.662518,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000002","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48602","scheme":"http","uri":"http://neko.domain/js/chunk-vendors.ff316984.js"} res={"bytes":410936,"elapsed":2.054964,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000003","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48604","scheme":"http","uri":"http://neko.domain/js/app.071b0bf3.js"} res={"bytes":149723,"elapsed":1.228712,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000004","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48618","scheme":"http","uri":"http://neko.domain/css/app.4dc310a0.css"} res={"bytes":346108,"elapsed":1.837917,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000005","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48626","scheme":"http","uri":"http://neko.domain/fonts/whitney-400.de6a82ab.woff"} res={"bytes":77784,"elapsed":0.374979,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000006","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48632","scheme":"http","uri":"http://neko.domain/emoji.json"} res={"bytes":187915,"elapsed":0.517997,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000007","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48638","scheme":"http","uri":"http://neko.domain/keyboard_layouts.json"} res={"bytes":1657,"elapsed":0.076323,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000008","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48648","scheme":"http","uri":"http://neko.domain/img/logo.800bec71.svg"} res={"bytes":4020,"elapsed":0.076954,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000009","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48652","scheme":"http","uri":"http://neko.domain/fonts/whitney-700.2a872bb1.woff"} res={"bytes":80000,"elapsed":0.393528,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000010","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48666","scheme":"http","uri":"http://neko.domain/fonts/fa-solid-900.3eae9857.woff2"} res={"bytes":150124,"elapsed":1.89997,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000011","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48680","scheme":"http","uri":"http://neko.domain/favicon-16x16.png"} res={"bytes":662,"elapsed":0.093225,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000012","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:48694","scheme":"http","uri":"http://neko.domain/favicon-32x32.png"} res={"bytes":1003,"elapsed":0.046119,"status":200,"time":"Mon, 10 Apr 2023 11:05:26 UTC"}
11:05AM DBG attempting to upgrade connection module=websocket
11:05AM INF creating pipeline codec=opus module=capture src="pulsesrc device=audio_output.monitor ! audio/x-raw,channels=2 ! audioconvert ! opusenc inband-fec=true bitrate=256000 ! appsink name=appsinkaudio" submodule=stream-sink video_id=audio
11:05AM INF first listener, starting module=capture submodule=stream-sink video_id=audio
11:05AM INF creating pipeline codec=vp8 module=capture src="ximagesrc display-name=:0.0 show-pointer=true use-damage=false ! video/x-raw,framerate=30/1 ! videoconvert ! queue !  vp8enc target-bitrate=1300000 cpu-used=4 end-usage=cbr threads=4 deadline=1 undershoot=95 buffer-size=8000 buffer-initial-size=4000 buffer-optimal-size=6000 keyframe-max-dist=25 min-quantizer=4 max-quantizer=20  ! appsink name=appsinkvideo" submodule=stream-sink video_id=video
11:05AM INF first listener, starting module=capture submodule=stream-sink video_id=video
11:05AM DBG new connection created address=[nginxIP]:43368 module=websocket session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF signaling state changed to have-local-offer module=webrtc submodule=pion subsystem=pc
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"signal/provide\",\"id\":\"54N8rysllhYzCdiZMDN_eytlyv0NmtTN\",\"sdp\":\"v=0\\r\\no=- 2047808546224901838 1681124730 IN IP4 0.0.0.0\\r\\ns=-\\r\\nt=0 0\\r\\na=fingerprint:sha-256 AE:D1:30:4D:B3:1E:6B:81:12:44:26:61:0C:B7:63:7B:37:16:C7:7E:EE:46:A6:F2:22:B1:19:74:1E:A8:08:A7\\r\\na=ice-lite\\r\\na=extmap-allow-mixed\\r\\na=group:BUNDLE 0 1 2\\r\\nm=video 9 UDP/TLS/RTP/SAVPF 96\\r\\nc=IN IP4 0.0.0.0\\r\\na=setup:actpass\\r\\na=mid:0\\r\\na=ice-ufrag:eBYOqtGzolUnsKXs\\r\\na=ice-pwd:yhByeleetMAUMGBdtZqSZyFyLCygocHl\\r\\na=rtcp-mux\\r\\na=rtcp-rsize\\r\\na=rtpmap:96 VP8/90000\\r\\na=rtcp-fb:96 transport-cc \\r\\na=rtcp-fb:96 goog-remb \\r\\na=rtcp-fb:96 ccm fir\\r\\na=rtcp-fb:96 nack pli\\r\\na=rtcp-fb:96 nack \\r\\na=rtcp-fb:96 nack \\r\\na=rtcp-fb:96 nack pli\\r\\na=rtcp-fb:96 transport-cc \\r\\na=extmap:1 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\\r\\na=ssrc:2918573238 cname:stream\\r\\na=ssrc:2918573238 msid:stream video\\r\\na=ssrc:2918573238 mslabel:stream\\r\\na=ssrc:2918573238 label:video\\r\\na=msid:stream video\\r\\na=sendrecv\\r\\nm=audio 9 UDP/TLS/RTP/SAVPF 111\\r\\nc=IN IP4 0.0.0.0\\r\\na=setup:actpass\\r\\na=mid:1\\r\\na=ice-ufrag:eBYOqtGzolUnsKXs\\r\\na=ice-pwd:yhByeleetMAUMGBdtZqSZyFyLCygocHl\\r\\na=rtcp-mux\\r\\na=rtcp-rsize\\r\\na=rtpmap:111 opus/48000/2\\r\\na=fmtp:111 useinbandfec=1;stereo=1\\r\\na=rtcp-fb:111 transport-cc \\r\\na=extmap:1 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\\r\\na=ssrc:2667016722 cname:stream\\r\\na=ssrc:2667016722 msid:stream audio\\r\\na=ssrc:2667016722 mslabel:stream\\r\\na=ssrc:2667016722 label:audio\\r\\na=msid:stream audio\\r\\na=sendrecv\\r\\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\\r\\nc=IN IP4 0.0.0.0\\r\\na=setup:actpass\\r\\na=mid:2\\r\\na=sendrecv\\r\\na=sctp-port:5000\\r\\na=ice-ufrag:eBYOqtGzolUnsKXs\\r\\na=ice-pwd:yhByeleetMAUMGBdtZqSZyFyLCygocHl\\r\\n\",\"lite\":true,\"ice\":[{\"credentialType\":\"password\",\"urls\":[\"stun:stun.l.google.com:19302\"]}]}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"system/init\",\"implicit_hosting\":false,\"locks\":{},\"file_transfer\":false}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF signal update - LocalCandidate id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=session
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"screen/configurations\",\"configurations\":{\"0\":{\"width\":1280,\"height\":720,\"rates\":{\"0\":30,\"1\":60}},\"1\":{\"width\":1152,\"height\":648,\"rates\":{\"0\":60}},\"10\":{\"width\":720,\"height\":400,\"rates\":{}},\"11\":{\"width\":640,\"height\":400,\"rates\":{}},\"12\":{\"width\":640,\"height\":360,\"rates\":{\"0\":60}},\"13\":{\"width\":640,\"height\":350,\"rates\":{}},\"2\":{\"width\":960,\"height\":720,\"rates\":{\"0\":60,\"1\":30}},\"3\":{\"width\":1024,\"height\":576,\"rates\":{\"0\":60}},\"4\":{\"width\":832,\"height\":624,\"rates\":{}},\"5\":{\"width\":960,\"height\":540,\"rates\":{\"0\":60}},\"6\":{\"width\":800,\"height\":600,\"rates\":{\"3\":60}},\"7\":{\"width\":864,\"height\":486,\"rates\":{\"0\":60}},\"8\":{\"width\":640,\"height\":480,\"rates\":{\"3\":60}},\"9\":{\"width\":720,\"height\":405,\"rates\":{\"0\":60}}}}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"broadcast/status\",\"url\":\"\",\"isActive\":false}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG session created id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=websocket
11:05AM DBG GetConn by ufrag: eBYOqtGzolUnsKXs module=webrtc submodule=pion subsystem=ice
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"signal/candidate\",\"data\":\"{\\\"candidate\\\":\\\"candidate:3949506420 1 udp 2130706431 [PublicIP] 60000 typ host\\\",\\\"sdpMid\\\":\\\"\\\",\\\"sdpMLineIndex\\\":0,\\\"usernameFragment\\\":null}\"}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF signal update - LocalCandidate id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=session
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"signal/candidate\",\"data\":\"{\\\"candidate\\\":\\\"candidate:1453055636 1 tcp 2124414975 [PublicIP] 60000 typ host tcptype passive\\\",\\\"sdpMid\\\":\\\"\\\",\\\"sdpMLineIndex\\\":0,\\\"usernameFragment\\\":null}\"}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF sent all ICECandidates module=webrtc
11:05AM DBG received message from client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"signal/answer\",\"sdp\":\"v=0\\r\\no=- 2930214188162236773 2 IN IP4 127.0.0.1\\r\\ns=-\\r\\nt=0 0\\r\\na=group:BUNDLE 0 1 2\\r\\na=extmap-allow-mixed\\r\\na=msid-semantic: WMS\\r\\nm=video 9 UDP/TLS/RTP/SAVPF 96\\r\\nc=IN IP4 0.0.0.0\\r\\na=rtcp:9 IN IP4 0.0.0.0\\r\\na=ice-ufrag:7O56\\r\\na=ice-pwd:z3cBshuUW7Ffq5UUXexOrUhS\\r\\na=ice-options:trickle\\r\\na=fingerprint:sha-256 A8:43:4F:BF:B5:EE:29:FB:E7:93:DD:77:64:5C:05:A8:33:F3:7D:A8:78:DF:8E:E9:2A:1D:16:80:BF:08:30:44\\r\\na=setup:active\\r\\na=mid:0\\r\\na=extmap:1 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\\r\\na=recvonly\\r\\na=rtcp-mux\\r\\na=rtcp-rsize\\r\\na=rtpmap:96 VP8/90000\\r\\na=rtcp-fb:96 goog-remb\\r\\na=rtcp-fb:96 transport-cc\\r\\na=rtcp-fb:96 ccm fir\\r\\na=rtcp-fb:96 nack\\r\\na=rtcp-fb:96 nack pli\\r\\nm=audio 9 UDP/TLS/RTP/SAVPF 111\\r\\nc=IN IP4 0.0.0.0\\r\\na=rtcp:9 IN IP4 0.0.0.0\\r\\na=ice-ufrag:7O56\\r\\na=ice-pwd:z3cBshuUW7Ffq5UUXexOrUhS\\r\\na=ice-options:trickle\\r\\na=fingerprint:sha-256 A8:43:4F:BF:B5:EE:29:FB:E7:93:DD:77:64:5C:05:A8:33:F3:7D:A8:78:DF:8E:E9:2A:1D:16:80:BF:08:30:44\\r\\na=setup:active\\r\\na=mid:1\\r\\na=extmap:1 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\\r\\na=recvonly\\r\\na=rtcp-mux\\r\\na=rtpmap:111 opus/48000/2\\r\\na=rtcp-fb:111 transport-cc\\r\\na=fmtp:111 minptime=10;useinbandfec=1;stereo=1\\r\\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\\r\\nc=IN IP4 0.0.0.0\\r\\nb=AS:30\\r\\na=ice-ufrag:7O56\\r\\na=ice-pwd:z3cBshuUW7Ffq5UUXexOrUhS\\r\\na=ice-options:trickle\\r\\na=fingerprint:sha-256 A8:43:4F:BF:B5:EE:29:FB:E7:93:DD:77:64:5C:05:A8:33:F3:7D:A8:78:DF:8E:E9:2A:1D:16:80:BF:08:30:44\\r\\na=setup:active\\r\\na=mid:2\\r\\na=sctp-port:5000\\r\\n\",\"displayname\":\"admin\"}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF signal update - RemoteAnswer id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=session
11:05AM INF signaling state changed to stable module=webrtc submodule=pion subsystem=pc
11:05AM DBG Started agent: isControlling? false, remoteUfrag: "7O56", remotePwd: "z3cBshuUW7Ffq5UUXexOrUhS" module=webrtc submodule=pion subsystem=ice
11:05AM INF Setting new connection state: Checking module=webrtc submodule=pion subsystem=ice
11:05AM INF ICE connection state changed: checking module=webrtc submodule=pion subsystem=pc
11:05AM INF connection state has changed connection_state=checking module=webrtc
11:05AM DBG adding a new peer-reflexive candidate: [ClientIP]:34638 module=webrtc submodule=pion subsystem=ice
11:05AM DBG Registered [ClientIP]:34638 for eBYOqtGzolUnsKXs module=webrtc submodule=pion subsystem=ice-udp
11:05AM DBG request complete (200) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000014","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:43372","scheme":"http","uri":"http://neko.domain/fonts/whitney-600.1bda32d7.woff"} res={"bytes":82688,"elapsed":1.059956,"status":200,"time":"Mon, 10 Apr 2023 11:05:30 UTC"}
11:05AM INF Setting new connection state: Connected module=webrtc submodule=pion subsystem=ice
11:05AM INF ICE connection state changed: connected module=webrtc submodule=pion subsystem=pc
11:05AM INF connection state has changed connection_state=connected module=webrtc
11:05AM DBG CipherSuite not initialized, queuing packet module=webrtc submodule=pion subsystem=dtls
11:05AM DBG received packet of next epoch, queuing packet module=webrtc submodule=pion subsystem=dtls
11:05AM INF peer connection state changed: connected module=webrtc submodule=pion subsystem=pc
11:05AM INF peer connected id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=webrtc
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"member/list\",\"members\":[{\"id\":\"54N8rysllhYzCdiZMDN_eytlyv0NmtTN\",\"displayname\":\"admin\",\"admin\":true,\"muted\":false}]}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"screen/resolution\",\"width\":1280,\"height\":720,\"rate\":30}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"member/connected\",\"id\":\"54N8rysllhYzCdiZMDN_eytlyv0NmtTN\",\"displayname\":\"admin\",\"admin\":true,\"muted\":false}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG session connected id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=websocket
11:05AM DBG request complete (206) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000015","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:43380","scheme":"http","uri":"http://neko.domain/chat.mp3"} res={"bytes":9229,"elapsed":0.152796,"status":206,"time":"Mon, 10 Apr 2023 11:05:30 UTC"}
11:05AM DBG received message from client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"control/request\"}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"control/locked\",\"id\":\"54N8rysllhYzCdiZMDN_eytlyv0NmtTN\"}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG received message from client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"control/keyboard\",\"layout\":\"us\"}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG received message from client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"control/keyboard\",\"capsLock\":false,\"numLock\":false,\"scrollLock\":false}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM DBG received message from client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"screen/set\",\"width\":800,\"height\":600,\"rate\":60}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF destroying pipeline module=capture submodule=stream-sink video_id=video
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"screen/resolution\",\"id\":\"54N8rysllhYzCdiZMDN_eytlyv0NmtTN\",\"width\":800,\"height\":600,\"rate\":60}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF creating pipeline codec=vp8 module=capture src="ximagesrc display-name=:0.0 show-pointer=true use-damage=false ! video/x-raw,framerate=30/1 ! videoconvert ! queue !  vp8enc target-bitrate=1300000 cpu-used=4 end-usage=cbr threads=4 deadline=1 undershoot=95 buffer-size=8000 buffer-initial-size=4000 buffer-optimal-size=6000 keyframe-max-dist=25 min-quantizer=4 max-quantizer=20  ! appsink name=appsinkvideo" submodule=stream-sink video_id=video
11:05AM DBG button down 1 module=webrtc
11:05AM DBG button up 1 module=webrtc
11:05AM DBG received message from client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"screen/set\",\"width\":1280,\"height\":720,\"rate\":30}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF destroying pipeline module=capture submodule=stream-sink video_id=video
11:05AM DBG sending message to client address=[nginxIP]:43368 module=websocket raw="{\"event\":\"screen/resolution\",\"id\":\"54N8rysllhYzCdiZMDN_eytlyv0NmtTN\",\"width\":1280,\"height\":720,\"rate\":30}" session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM INF creating pipeline codec=vp8 module=capture src="ximagesrc display-name=:0.0 show-pointer=true use-damage=false ! video/x-raw,framerate=30/1 ! videoconvert ! queue !  vp8enc target-bitrate=1300000 cpu-used=4 end-usage=cbr threads=4 deadline=1 undershoot=95 buffer-size=8000 buffer-initial-size=4000 buffer-optimal-size=6000 keyframe-max-dist=25 min-quantizer=4 max-quantizer=20  ! appsink name=appsinkvideo" submodule=stream-sink video_id=video
11:05AM DBG button down 1 module=webrtc
11:05AM DBG button up 1 module=webrtc
11:05AM WRN read message error error="websocket: close 1005 (no status)" module=websocket
11:05AM DBG handle socket ending address=[nginxIP]:43368 module=websocket
11:05AM DBG session ended address=[nginxIP]:43368 module=websocket session=54N8rysllhYzCdiZMDN_eytlyv0NmtTN
11:05AM WRN Warning: mux: no endpoint for packet starting with 23 module=webrtc submodule=pion subsystem=mux
11:05AM DBG request complete (0) module=http req={"agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36","id":"neko/2c7jHlXN4E-000013","method":"GET","proto":"HTTP/1.1","remote":"[nginxIP]:43368","scheme":"http","uri":"http://neko.domain/ws?password=admin"} res={"bytes":0,"elapsed":19508.149369,"status":0,"time":"Mon, 10 Apr 2023 11:05:50 UTC"}
11:05AM WRN Failed to read from candidate tcp4 host [PublicIP]:60000: io: read/write on closed pipe module=webrtc submodule=pion subsystem=ice
11:05AM WRN Failed to accept RTCP stream is already closed module=webrtc submodule=pion subsystem=pc
11:05AM INF Setting new connection state: Closed module=webrtc submodule=pion subsystem=ice
11:05AM INF peer connection state changed: closed module=webrtc submodule=pion subsystem=pc
11:05AM WRN Failed to accept RTP stream is already closed module=webrtc submodule=pion subsystem=pc
11:05AM INF peer closed id=54N8rysllhYzCdiZMDN_eytlyv0NmtTN module=webrtc
11:05AM INF ICE connection state changed: closed module=webrtc submodule=pion subsystem=pc
11:05AM INF connection state has changed connection_state=closed module=webrtc
11:05AM DBG attempting to upgrade connection module=websocket
11:06AM DBG attempting to upgrade connection module=websocket

Seems like changing the resolution works fine.. Each subsequent login attempt adds DBG attempting to upgrade connection module=websocket to the log (but connecting still times out).

m1k1o commented 1 year ago

That means creating/destroying pipeline alone is working correctly.

I see first listener, starting where it starts the pipeline, but i am missing last listener, stopping. So after last user left the room, pipeline was not stopped. But it maybe tried to do so and ended up somehow blocked.

I also do not see destroying session, basically last 5 messages from your v2.7 that are not in v2.8:

9:15AM INF destroying pipeline module=capture submodule=stream-sink video_id=audio
9:15AM INF last listener, stopping module=capture submodule=stream-sink video_id=audio
9:15AM INF destroying pipeline module=capture submodule=stream-sink video_id=video
9:15AM INF last listener, stopping module=capture submodule=stream-sink video_id=video
9:15AM INF destroying session module=session session_id=dyUB-wXo35CaQmE1BknxYpFCWAYvvYho

If you don't log out only close the tab, does it happen? Or have you meant by logging out just closing the tab?

darnfinecoffee commented 1 year ago

If you don't log out only close the tab, does it happen? Or have you meant by logging out just closing the tab?

Yes, it still happens. Closing the tab or clicking on "log out" seems to make no difference.

innerop commented 1 year ago

Sorry to interject here, but is this happening for both EPR and MUX based setups?

m1k1o commented 1 year ago

The same thing happens no matter if I use the udpmux or epr setting.

@innerop yes, as stated by the author and i also tried both. Though I still cannot replicate it.

innerop commented 1 year ago

Ok, I'm about to start it and see, so I'll give it a try and see. My instance is hosted in the public cloud, not sure if that makes a difference. I'm also not sure of choice of browser makes a difference. I've set mine to google-chrome

innerop commented 1 year ago

Is there a changelog or tagged releases so we can see what changed in v2.8?

innerop commented 1 year ago

@m1k1o I can't replicate it either.

But I have lots of questions now that I got it up and running. First, let's see what changed in v2.8. I am fluent in Go, JS, and WebRTC, so I might be able to help.

m1k1o commented 1 year ago

I'm also not sure of choice of browser makes a difference. I've set mine to google-chrome

It does not matter, since this is likely some issue in the go codebase itself. That is the same for all apps, its built in m1k1o/neko:base.

@innerop here is diff what changed between v2.7...v2.8. I suspect that this bigger refactoring could be root of this problems, since we added lots of channels and they might block if used incorrectly or in some rare edge case.

@darnfinecoffee could you check please if v2.7.1 works and if v2.7.2 does not work anymore? So that we can narrow it down to the refactoring.

darnfinecoffee commented 1 year ago

I've identified the problematic commit! Seems like 0dd9597 is what causes the issue. Adding the load-module line from that commit to my pulseaudio config seems to fix the issue.

m1k1o commented 1 year ago

Great! So its caused by audio, that means also audio was not working for you. You could also revert to the old one by adding device: auto_null.monitor to your config.

@innerop it can be reproduced by setting device to something that does not exist e.g. -e "NEKO_DEVICE=foo".

It would be still interesting what causes the deadlock, but its probably gstreamer pipeline that cannot stop. When changing screen it stops only video pipeline, so it makes sense.

innerop commented 1 year ago

@m1k1o

What if, as a work around or for safety, just check that the device exist?

maybe something like 

func checkAudioDeviceAvailable(device string) bool {
    source, err := glib.NewMainContext(glib.PriorityDefault)
    if err != nil {
        return false
    }

    loop := glib.NewMainLoop(source, false)
    found := false

    // Check if the audio device is available using the GstDeviceMonitor
    gst.DeviceMonitorNew(func(dm *gst.DeviceMonitor) {
        dm.AddFilter("Audio/Source", nil)
        dm.Connect("device-added", func(_ *glib.Object, dev *gst.Device) {
            if dev.GetName() == device {
                found = true
                loop.Quit()
            }
        })
        dm.Start()
    })

    // Run the loop for a short duration to search for the device
    glib.TimeoutAdd(500, func() bool {
        loop.Quit()
        return false
    })

    loop.Run()

    return found
}

uses gtk3/glib

I just googled it.... no familiarity with gstreamer or gtk

innerop commented 1 year ago

The above would go here:

gst/pipelines/

func NewAudioPipeline(rtpCodec codec.RTPCodec, device string, pipelineSrc string, bitrate uint) (string, error) {
    // Check if the audio device is available
    if !checkAudioDeviceAvailable(device) {
        return "", fmt.Errorf("audio device %s not available", device)
    }

    // Rest of the NewAudioPipeline function...
}
m1k1o commented 1 year ago

@innerop Thank you for the suggestion.

I am more concerned about why gstreamer did not complain that the audio device does not exist. When trying to set non-existing display -e "NEKO_DISPLAY=foo" it does not work, again does not produce any error, but does not freeze.

Maybe adding context.Context or at least some timeout to the destroy function would be a good solution.

https://github.com/m1k1o/neko/blob/b2080649ea50d942c3e9887813d867edbfc21052/server/internal/capture/gst/gst.go#L96-L105

But that could cause memory leaks in C code when not destroyed properly.

I tried locally starting gstreamer pipeline with nonexisting device and it fails immediatly. Maybe we did not catch that error and we still think that pipeline is running although is not and we attempt to destroy it what causes deadlock.

$ gst-launch-1.0 pulsesrc device=foo ! audio/x-raw,channels=2 ! audioconvert ! opusenc inband-fec=true bitrate=128000 ! autoaudiosink
Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
Setting pipeline to PLAYING ...
New clock: GstPulseSrcClock
ERROR: from element /GstPipeline:pipeline0/GstPulseSrc:pulsesrc0: Internal data stream error.
Additional debug info:
gstbasesrc.c(3072): gst_base_src_loop (): /GstPipeline:pipeline0/GstPulseSrc:pulsesrc0:
streaming stopped, reason not-negotiated (-4)
Execution ended after 0:00:00.000106250
Setting pipeline to NULL ...
Freeing pipeline ...
innerop commented 1 year ago

yes, agreed, always best to fix the error handling than to try and avoid creating the error (since it can happen for another reason) ... good idea... but at least it's not preventing the proper use of the app