search

murat-dogan / node-datachannel

WebRTC For Node.js and Electron. libdatachannel node bindings.
Mozilla Public License 2.0
292 stars 55 forks source link

TURN over TLS does not work #167

Closed mghadam closed 6 months ago

mghadam commented 1 year ago

I am testing node-datachannel with libnice to use TURN over TLS turns:username:password@turnserver.domain:TLSPort

The hello world script does not run, here is its logs:

2023-07-16 08:36:24.529 DEBUG [335595] [rtc::impl::Init::doInit@110] Global initialization
2023-07-16 08:36:24.533 DEBUG [335603] [rtc::impl::Certificate::Generate@52] Generating certificate (GnuTLS)
2023-07-16 08:36:24.533 DEBUG [335604] [rtc::impl::Certificate::Generate@52] Generating certificate (GnuTLS)
2023-07-16 08:36:24.533 DEBUG [335595] [rtc::impl::IceTransport::IceTransport@377] Initializing ICE transport (libnice)
2023-07-16 08:36:24.919 INFO  [335595] [rtc::impl::IceTransport::IceTransport@544] Using TURN server "turn2.MYDOMAIN.com:443"
2023-07-16 08:36:24.919 DEBUG [335595] [rtc::impl::PeerConnection::processLocalDescription@934] Adding application to local description, mid="0"
2023-07-16 08:36:24.919 INFO  [335595] [rtc::impl::PeerConnection::changeSignalingState@1175] Changed signaling state to have-local-offer
2023-07-16 08:36:24.919 INFO  [335595] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to in-progress
Peer1 SDP: v=0
o=rtc 3631761112 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
a=setup:actpass
a=ice-ufrag:xRck
a=ice-pwd:Ytqm68iTNKElIKJtDGN4H8
a=ice-options:trickle
a=fingerprint:sha-256 61:4F:32:AB:ED:AB:33:48:83:83:3D:A5:EF:40:D8:6A:AD:AB:24:B1:C4:0F:33:C4:D2:EC:E1:85:2F:A8:74:38
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 0.0.0.0
a=mid:0
a=sendrecv
a=sctp-port:5000
a=max-message-size:262144
  Type: offer
2023-07-16 08:36:24.946 DEBUG [335595] [rtc::impl::IceTransport::IceTransport@377] Initializing ICE transport (libnice)
2023-07-16 08:36:25.053 INFO  [335595] [rtc::impl::IceTransport::IceTransport@544] Using TURN server "turn2.MYDOMAIN.com:443"
2023-07-16 08:36:25.053 INFO  [335595] [rtc::impl::PeerConnection::changeSignalingState@1175] Changed signaling state to have-remote-offer
2023-07-16 08:36:25.053 DEBUG [335595] [rtc::impl::PeerConnection::processLocalDescription@840] Reciprocating application in local description, mid="0"
2023-07-16 08:36:25.053 INFO  [335595] [rtc::impl::PeerConnection::changeSignalingState@1175] Changed signaling state to stable
2023-07-16 08:36:25.053 INFO  [335595] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to in-progress
Peer2 SDP: v=0
o=rtc 1420610307 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
a=setup:active
a=ice-ufrag:EVHI
a=ice-pwd:fNgFYQ7ZEQT2LcKkRdIT78
a=ice-options:trickle
a=fingerprint:sha-256 B6:69:64:BA:B2:7B:CB:41:88:B7:2D:A7:B3:86:35:10:92:77:B9:05:B5:CA:69:27:10:E2:34:E5:B6:20:6F:52
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 0.0.0.0
a=mid:0
a=sendrecv
a=sctp-port:5000
a=max-message-size:262144
  Type: answer
2023-07-16 08:36:25.059 INFO  [335595] [rtc::impl::PeerConnection::changeSignalingState@1175] Changed signaling state to stable
2023-07-16 08:36:26.939 INFO  [335609] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to complete
2023-07-16 08:36:27.070 INFO  [335609] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to complete
/etc/node-datachannel/datachannel.js:67
    dc2.close();
        ^

TypeError: Cannot read property 'close' of null
    at Timeout._onTimeout (/etc/node-datachannel/datachannel.js:67:9)
    at listOnTimeout (internal/timers.js:554:17)
    at processTimers (internal/timers.js:497:7)

The issue is the same when compiling node-datachannel with Openssl.

In the eturnal server log, I see that its SSL connection gets reset:

2023-07-16 08:41:36.079021+03:30 [info] Accepting connection: CLIENTIP:10404 -> SERVERIP:443 [TLS, session 0ve5y4wamjaa]
2023-07-16 08:41:45.805239+03:30 [info] Connection reset by peer [TLS, session x7j2n58yt9wx, anonymous, client CLIENTIP:41709]

I am using the same turn server over tls using RTCPeerConnection in web browsers without any issues. This problem only exists on Turn+TLS. Turn+TCP works fine.

Any ideas how to debug this issue?

paullouisageneau commented 1 year ago

You should run with verbose logging to get log information from libnice.

murat-dogan commented 1 year ago

TypeError: Cannot read property 'close' of null This error occurs because the data channel is not opened. I will add an if condition anyway.

mghadam commented 1 year ago

Thank you, I now see two related errors Not issuing local candidate because of transport policy and bind discovery timed out, aborting discovery item.

The first error also exists when using working TCP transport instead of TLS. The latter bind discovery timed out error only happens when using TLS and is apparently causing this problem. Any ideas where this error comes from?

Here are the related lines in verbose logging:

2023-07-16 17:46:30.180 VERB  [378153] [rtc::impl::PeerConnection::validateRemoteDescription@805] Remote description looks valid
2023-07-16 17:46:30.180 INFO  [378153] [rtc::impl::PeerConnection::changeSignalingState@1175] Changed signaling state to stable
2023-07-16 17:46:30.729 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : discovery tick #51 with list 0x55b9ec2050 (1)
2023-07-16 17:46:31.357 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : discovery tick #101 with list 0x55b9ec2050 (1)
2023-07-16 17:46:31.984 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : discovery tick #151 with list 0x55b9ec2050 (1)
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000 : Candidate gathering FINISHED, stopping discovery timer.
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000: gathered UDP local candidate : [10.0.1.6]:42435 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000: gathered UDP local candidate : [10.10.1.6]:13297 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.035 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000: gathered UDP local candidate : [192.168.8.2]:38672 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.036 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18000: gathered UDP local candidate : [192.168.1.15]:46541 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.036 INFO  [378166] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to complete
2023-07-16 17:46:32.185 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0 : bind discovery timed out, aborting discovery item.
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0 : Candidate gathering FINISHED, stopping discovery timer.
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0: gathered UDP local candidate : [10.0.1.6]:39864 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0: gathered UDP local candidate : [10.10.1.6]:8344 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0: gathered UDP local candidate : [192.168.8.2]:54374 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.186 VERB  [378166] [rtc::impl::IceTransport::LogCallback@847] nice: Agent 0x55b9f18bd0: gathered UDP local candidate : [192.168.1.15]:59482 for s1/c1. U/P '(null)'/'(null)'
2023-07-16 17:46:32.186 INFO  [378166] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to complete
2023-07-16 17:46:40.031 VERB  [378153] [rtc::impl::DataChannel::close@87] Closing DataChannel
2023-07-16 17:46:40.031 VERB  [378153] [rtc::impl::DataChannel::close@87] Closing DataChannel
2023-07-16 17:46:40.032 VERB  [378153] [rtc::impl::DataChannel::~DataChannel@81] Destroying DataChannel
2023-07-16 17:46:40.032 VERB  [378153] [rtc::impl::DataChannel::close@87] Closing DataChannel
paullouisageneau commented 1 year ago

It looks like the error bind discovery timed out means the request to the TURN server timed out in libnice. The phrasing is quite weird though, as the library should send an allocate request immediately, not a bind request.

If it works for TURN over TCP, then I think it might mean that the timeout is actually too short (the corresponding property is stun_reliable_timeout, and the default seems to be 2s which looks long enough), or it might indicate a compatibility bug between libnice and the eturnal server. Could you try a different TURN server to be sure?

mghadam commented 1 year ago

it indeed works with coturn for direct connections:

2023-07-19 18:12:56.712 INFO  [254337] [rtc::impl::PeerConnection::changeState@1144] Changed state to connecting
2023-07-19 18:12:56.736 INFO  [254350] [rtc::impl::PeerConnection::changeGatheringState@1162] Changed gathering state to complete
2023-07-19 18:12:57.293 DEBUG [254350] [rtc::impl::DtlsTransport::DtlsTransport@45] Initializing DTLS transport (GnuTLS)
2023-07-19 18:12:57.293 DEBUG [254350] [rtc::impl::DtlsTransport::start@104] Starting DTLS recv thread
2023-07-19 18:12:57.293 DEBUG [254350] [rtc::impl::DtlsTransport::DtlsTransport@45] Initializing DTLS transport (GnuTLS)
2023-07-19 18:12:57.293 DEBUG [254350] [rtc::impl::DtlsTransport::start@104] Starting DTLS recv thread
2023-07-19 18:12:57.546 INFO  [254353] [rtc::impl::DtlsTransport::runRecvLoop@202] DTLS handshake finished
2023-07-19 18:12:57.546 DEBUG [254353] [rtc::impl::SctpTransport::SctpTransport@174] Initializing SCTP transport
2023-07-19 18:12:57.546 DEBUG [254353] [rtc::impl::SctpTransport::connect@355] SCTP connecting (local port=5000, remote port=5000)
2023-07-19 18:12:57.596 INFO  [254352] [rtc::impl::DtlsTransport::runRecvLoop@202] DTLS handshake finished
2023-07-19 18:12:57.596 DEBUG [254352] [rtc::impl::SctpTransport::SctpTransport@174] Initializing SCTP transport
2023-07-19 18:12:57.597 DEBUG [254352] [rtc::impl::SctpTransport::connect@355] SCTP connecting (local port=5000, remote port=5000)
2023-07-19 18:12:57.597 DEBUG [254344] [rtc::impl::SctpTransport::processNotification@839] SCTP negotiated streams: incoming=1024, outgoing=1024
2023-07-19 18:12:57.597 DEBUG [254345] [rtc::impl::SctpTransport::processNotification@839] SCTP negotiated streams: incoming=1024, outgoing=1024
2023-07-19 18:12:57.597 INFO  [254345] [rtc::impl::SctpTransport::processNotification@844] SCTP connected
2023-07-19 18:12:57.597 INFO  [254345] [rtc::impl::PeerConnection::changeState@1144] Changed state to connected

However, if I use a nginx reverse proxy in front of coturn as explained here, it won't work. Trickle ICE shows a valid working TURNS coturn server in my nginx+coturn setup.

Another note here, coturn accepts UDP/TCP/TLS via its tls-listening-port as explained in the config file. This is not the case with eturnal, it has a separate port for tls and does not accept any transport other than TLS over it.

paullouisageneau commented 1 year ago

However, if I use a nginx reverse proxy in front of coturn as explained here, it won't work. Trickle ICE shows a valid working TURNS coturn server in my nginx+coturn setup.

This sounds like a libnice bug then. What version of libnice do you use?

mghadam commented 1 year ago

However, if I use a nginx reverse proxy in front of coturn as explained here, it won't work. Trickle ICE shows a valid working TURNS coturn server in my nginx+coturn setup.

This sounds like a libnice bug then. What version of libnice do you use?

It is v0.1.21 in debian bookworm repo.

murat-dogan commented 6 months ago

I am closıng the issue if you don't mind.

Please feel free to open if you need to.