node-datachannel icon indicating copy to clipboard operation
node-datachannel copied to clipboard

Published 20 hours ago • verified publisher icon murat-dogan

Crash when using inside a worker

Open oanguenot opened this issue 1 year ago • 8 comments

Using Node LTS (v16.17.0), I tried to load and execute node-datachannel into a Node worker_threads.

It seems to start correctly, but I have the following error: FATAL ERROR: HandleScope::HandleScope Entering the V8 API without proper locking in place

Here is the complete logs captured from the worker 2022-08-30 16:54:08.968 DEBUG [1837469] [rtc::impl::Init::doInit@120] Global initialization 2022-08-30 16:54:09.103 DEBUG [1837472] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL) 2022-08-30 16:54:09.103 VERB [1837469] [rtc::impl::PeerConnection::PeerConnection@59] Creating PeerConnection 2022-08-30 16:54:09.104 VERB [1837469] [rtc::impl::PeerConnection::PeerConnection@59] Creating PeerConnection 2022-08-30 16:54:09.104 DEBUG [1837471] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL) 2022-08-30 16:54:09.110 VERB [1837469] [rtc::PeerConnection::setLocalDescription@87] Setting local description, type=unspec 2022-08-30 16:54:09.110 VERB [1837469] [rtc::impl::PeerConnection::initIceTransport@146] Starting ICE transport 2022-08-30 16:54:09.110 DEBUG [1837469] [rtc::impl::IceTransport::IceTransport@58] Initializing ICE transport (libjuice) 2022-08-30 16:54:09.110 VERB [1837472] [rtc::impl::Certificate::Generate@239] Generating ECDSA P-256 key pair 2022-08-30 16:54:09.110 VERB [1837471] [rtc::impl::Certificate::Generate@239] Generating ECDSA P-256 key pair 2022-08-30 16:54:09.116 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Creating agent 2022-08-30 16:54:09.122 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Using random() for random bytes 2022-08-30 16:54:09.123 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Created local description: ufrag="8/1y", pwd="Kw0ONnHlyyU1b1uwWg26ky" 2022-08-30 16:54:09.123 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Generated local SDP description: a=ice-ufrag:8/1y a=ice-pwd:Kw0ONnHlyyU1b1uwWg26ky a=ice-options:ice2,trickle

2022-08-30 16:54:09.123 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Assuming controlling mode 2022-08-30 16:54:09.123 DEBUG [1837469] [rtc::impl::PeerConnection::processLocalDescription@948] Adding application to local description, mid="0" 2022-08-30 16:54:09.136 VERB [1837469] [rtc::impl::PeerConnection::processLocalDescription@964] Issuing local description: v=0 o=rtc 2003054121 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:8/1y a=ice-pwd:Kw0ONnHlyyU1b1uwWg26ky a=ice-options:ice2,trickle a=fingerprint:sha-256 FF:A9:2B:12:56:01:DC:F1:8D:02:49:C1:3F:48:06:64:A9:8B:46:4B:ED:FB:86:E6:DB:5E:0C:B2:FF:A0:64:3F 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

2022-08-30 16:54:09.136 INFO [1837469] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to have-local-offer 2022-08-30 16:54:09.136 INFO [1837469] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to in-progress 2022-08-30 16:54:09.136 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Gathering candidates 2022-08-30 16:54:09.136 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Creating connections registry 2022-08-30 16:54:09.136 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Starting connections thread 2022-08-30 16:54:09.136 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Creating connection FATAL ERROR: HandleScope::HandleScope Entering the V8 API without proper locking in place 1: 0x1058f5205 node::Abort() (.cold.1) [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 2: 0x1045f64d9 node::Abort() [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 3: 0x1045f664f node::OnFatalError(char const*, char const*) [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 4: 0x10476bbc1 v8::HandleScope::HandleScope(v8::Isolate*) [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 2022-08-30 16:54:09.153 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: UDP socket bound to any:57999 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Interrupting connections thread 2022-08-30 16:54:09.154 INFO [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to gathering 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Adding 1 local host candidates 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Gathered host candidate: a=candidate:1 1 UDP 2122317823 10.64.4.254 57999 typ host 2022-08-30 16:54:09.154 VERB [1837469] [rtc::Candidate::parse@100] Parsing candidate: 1 1 UDP 2122317823 xx.xx.xx.xx 57999 typ host 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::PeerConnection::processLocalCandidate@1003] Issuing local candidate: a=candidate:1 1 UDP 2122317823 xx.xx.xx.xx 57999 typ host 2022-08-30 16:54:09.154 VERB [1837469] [rtc::Candidate::resolve@144] Resolving candidate (mode=simple): xx.xx.xx.xx 57999 2022-08-30 16:54:09.154 VERB [1837469] [rtc::Candidate::resolve@179] Resolved candidate: xx.xx.xx.xx 57999 2022-08-30 16:54:09.154 INFO [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connecting 2022-08-30 16:54:09.154 INFO [1837469] [rtc::impl::PeerConnection::changeState@1151] Changed state to connecting 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Interrupting connections thread 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Resolving servers synchronously 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Updating gathering status 2022-08-30 16:54:09.154 INFO [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Candidate gathering done 2022-08-30 16:54:09.154 INFO [1837469] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to complete 2022-08-30 16:54:09.154 VERB [1837469] [rtc::impl::IceTransport::LogCallback@354] juice: Interrupting connections thread 5: 0x1045b3888 napi_open_handle_scope [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 2022-08-30 16:54:09.155 VERB [1837481] [rtc::impl::IceTransport::LogCallback@354] juice: Entering poll on 1 sockets for 0 ms 2022-08-30 16:54:09.155 VERB [1837481] [rtc::impl::IceTransport::LogCallback@354] juice: Leaving poll 2022-08-30 16:54:09.161 VERB [1837481] [rtc::impl::IceTransport::LogCallback@354] juice: Bookkeeping... 6: 0x111a21623 ThreadSafeCallback::Impl::async_callback() [/Users/oan/github/QuickCafeClient/node_modules/node-datachannel/build/Release/node_datachannel.node] 2022-08-30 16:54:09.164 VERB [1837481] [rtc::impl::IceTransport::LogCallback@354] juice: Entering poll on 1 sockets for 9998 ms 7: 0x111a214ce ThreadSafeCallback::Impl::static_async_callback(uv_async_s*) [/Users/oan/github/QuickCafeClient/node_modules/node-datachannel/build/Release/node_datachannel.node] 8: 0x104fb9aeb uv__async_io [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 9: 0x104fcd8bb uv__io_poll [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 10: 0x104fba071 uv_run [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 11: 0x10452a733 node::SpinEventLoop(node::Environment*) [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 12: 0x104635c51 node::NodeMainInstance::Run(int*, node::Environment*) [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 13: 0x1046358d3 node::NodeMainInstance::Run() [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 14: 0x1045c3bd2 node::Start(int, char**) [/Users/oan/.volta/tools/image/node/16.17.0/bin/node] 15: 0x1191b24fe

Not use of the support of node-datachannel into a Node worker thread.

oanguenot avatar Aug 30 '22 15:08 oanguenot

  • Could you please share your setup, sample code?
  • Are you using docker?

murat-dogan avatar Aug 31 '22 13:08 murat-dogan

HI @murat-dogan, I'm not using Docker. I use a Mac M1 with Monterey + Node 16.17.0

I have a module which loads a worker:

...
const { Worker } = require("worker_threads");
worker = new Worker("./modules/myWorker.js", { workerData: {} });
worker.postMessage({iceServers1, iceServers2});

Then inside that worker, I load and use node-datachannel to try a connection with 2 peers through a turn server

//myWorker.js
...
let nodeDataChannel = require('node-datachannel');
const { parentPort } = require("worker_threads");

parentPort.on("message", async (data) => {
  try {
  ...
  nodeDataChannel.initLogger("Verbose");
  
  const peer1 = new nodeDataChannel.PeerConnection("Peer1", { iceServers: data.iceServers1, iceTransportPolicy: "relay" });
  const peer2 = new nodeDataChannel.PeerConnection("Peer2", { iceServers: data.iceServers2, iceTransportPolicy: "relay"});
  
  peer1.onLocalDescription((sdp, type) => {
     peer2.setRemoteDescription(sdp, type);
  });
  peer1.onLocalCandidate((candidate, mid) => {
      peer2.addRemoteCandidate(candidate, mid);
  });
  peer2.onLocalDescription((sdp, type) => {
      peer1.setRemoteDescription(sdp, type);
  });
    peer2.onLocalCandidate((candidate, mid) => {
      peer1.addRemoteCandidate(candidate, mid);
  });

  dc1 = peer1.createDataChannel("test");
  dc1.onOpen(() => {
      dc1.sendMessage("Hello from Peer1");
  });
  dc1.onMessage((msg) => {
     ...
  });
  peer2.onDataChannel((dc) => {
      dc2.onMessage((msg) => {
       ...
       });
      dc2.sendMessage("Hello From Peer2");
  });
}

Same code works fine outside a worker.

oanguenot avatar Aug 31 '22 18:08 oanguenot

@murat-dogan I think it could come from how callbacks are scheduled. Possibly it tries to execute the callback of the worker on the main event loop.

paullouisageneau avatar Aug 31 '22 20:08 paullouisageneau

@paullouisageneau Normally V8 engine provides isolated environment for all worker_threads as I know. I made some tests and it really seems about callbacks.

We are still using old napi-thread-safe-callback . Disabling this by deleting LEGACY_NAPI_THREAD_SAFE_CALLBACK makes the trick but comes with an other error. The error is related to package napi-thread-safe-callback-cancellable. But this error does not seem related to worker thread. When I started it as main app, I got the same result.

If we could solve this problem then we can disable legacy mode for node >12

2022-09-01 09:17:10.999 DEBUG [21191] [rtc::impl::Init::doInit@120] Global initialization
2022-09-01 09:17:11.002 DEBUG [21192] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL)
2022-09-01 09:17:11.003 DEBUG [21193] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL)
2022-09-01 09:17:11.003 DEBUG [21191] [rtc::impl::IceTransport::IceTransport@58] Initializing ICE transport (libjuice)
2022-09-01 09:17:11.003 INFO  [21191] [rtc::impl::IceTransport::IceTransport@114] Using STUN server "stun.l.google.com:19302"
2022-09-01 09:17:11.003 DEBUG [21191] [rtc::impl::PeerConnection::processLocalDescription@948] Adding application to local description, mid="0"
2022-09-01 09:17:11.003 INFO  [21191] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to have-local-offer
2022-09-01 09:17:11.003 INFO  [21191] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to in-progress
2022-09-01 09:17:11.004 INFO  [21191] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to gathering
2022-09-01 09:17:11.004 INFO  [21191] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connecting
2022-09-01 09:17:11.004 INFO  [21191] [rtc::impl::PeerConnection::changeState@1151] Changed state to connecting
2022-09-01 09:17:11.006 DEBUG [21191] [rtc::impl::IceTransport::IceTransport@58] Initializing ICE transport (libjuice)
2022-09-01 09:17:11.006 INFO  [21191] [rtc::impl::IceTransport::IceTransport@114] Using STUN server "stun.l.google.com:19302"
2022-09-01 09:17:11.006 INFO  [21191] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to have-remote-offer
2022-09-01 09:17:11.006 DEBUG [21191] [rtc::impl::PeerConnection::processLocalDescription@866] Reciprocating application in local description, mid="0"
2022-09-01 09:17:11.007 INFO  [21191] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to stable
2022-09-01 09:17:11.007 INFO  [21191] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to in-progress
Peer1 State: connecting
2022-09-01 09:17:11.018 INFO  [21199] [rtc::impl::IceTransport::LogCallback@354] juice: Using STUN server stun.l.google.com:19302
2022-09-01 09:17:11.018 INFO  [21191] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to gathering
2022-09-01 09:17:11.018 INFO  [21191] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connecting
2022-09-01 09:17:11.018 INFO  [21191] [rtc::impl::PeerConnection::changeState@1151] Changed state to connecting
2022-09-01 09:17:11.019 INFO  [21200] [rtc::impl::IceTransport::LogCallback@354] juice: Using STUN server stun.l.google.com:19302
2022-09-01 09:17:11.020 INFO  [21191] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to stable
Peer1 GatheringState: in-progress
Peer1 SDP: v=0
o=rtc 1085502880 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:9LTF
a=ice-pwd:3oYE81cpCSTcYPg+VuZu3H
a=ice-options:ice2,trickle
a=fingerprint:sha-256 EB:69:12:B0:1B:C4:4C:7F:1B:22:F9:53:65:4F:02:0F:82:4E:6A:12:29:BD:21:41:F5:01:C6:50:AC:4A:84:56
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
Peer1 Candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 54008 typ host
Peer1 Candidate: a=candidate:2 1 UDP 2122317567 172.19.0.1 54008 typ host
Peer1 Candidate: a=candidate:3 1 UDP 2122317311 172.18.0.1 54008 typ host
Peer1 Candidate: a=candidate:4 1 UDP 2122317055 172.20.0.1 54008 typ host
Peer1 Candidate: a=candidate:5 1 UDP 2122316799 172.21.0.1 54008 typ host
Peer2 State: connecting
Peer2 GatheringState: in-progress
Peer2 SDP: v=0
o=rtc 2228317412 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:7L8N
a=ice-pwd:9F4VdPqNQMSmoLy5zlthhN
a=ice-options:ice2,trickle
a=fingerprint:sha-256 B0:D0:7C:5A:38:61:A4:2A:F8:C7:33:31:15:BC:D2:1E:0C:4F:F6:EB:E7:94:22:22:64:06:7E:8E:06:D3:9B:36
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
Peer2 Candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 42556 typ host
Peer2 Candidate: a=candidate:2 1 UDP 2122317567 172.19.0.1 42556 typ host
Peer2 Candidate: a=candidate:3 1 UDP 2122317311 172.18.0.1 42556 typ host
Peer2 Candidate: a=candidate:4 1 UDP 2122317055 172.20.0.1 42556 typ host
Peer2 Candidate: a=candidate:5 1 UDP 2122316799 172.21.0.1 42556 typ host
2022-09-01 09:17:11.067 WARN  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Send failed, errno=101
2022-09-01 09:17:11.067 WARN  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: STUN message send failed
2022-09-01 09:17:11.068 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: STUN server binding failed
2022-09-01 09:17:11.069 WARN  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Send failed, errno=101
2022-09-01 09:17:11.069 WARN  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: STUN message send failed
2022-09-01 09:17:11.069 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: STUN server binding failed
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: STUN server binding successful
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Got STUN mapped address 88.248.96.126:54008 from server
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Candidate gathering done
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to complete
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: STUN server binding successful
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Got STUN mapped address 88.248.96.126:42556 from server
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Candidate gathering done
2022-09-01 09:17:11.070 INFO  [21198] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to complete
Peer1 Candidate: a=candidate:6 1 UDP 1686108927 88.248.96.126 54008 typ srflx raddr 0.0.0.0 rport 0
Peer2 GatheringState: complete
Peer2 Candidate: a=candidate:6 1 UDP 1686108927 88.248.96.126 42556 typ srflx raddr 0.0.0.0 rport 0
Peer1 GatheringState: complete
2022-09-01 09:17:11.118 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connected
2022-09-01 09:17:11.118 DEBUG [21198] [rtc::impl::DtlsTransport::DtlsTransport@383] Initializing DTLS transport (OpenSSL)
2022-09-01 09:17:11.118 DEBUG [21198] [rtc::impl::DtlsTransport::start@472] Starting DTLS recv thread
2022-09-01 09:17:11.118 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to completed
2022-09-01 09:17:11.419 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connected
2022-09-01 09:17:11.419 DEBUG [21198] [rtc::impl::DtlsTransport::DtlsTransport@383] Initializing DTLS transport (OpenSSL)
2022-09-01 09:17:11.420 DEBUG [21198] [rtc::impl::DtlsTransport::start@472] Starting DTLS recv thread
2022-09-01 09:17:11.426 INFO  [21201] [rtc::impl::DtlsTransport::runRecvLoop@565] DTLS handshake finished
2022-09-01 09:17:11.426 DEBUG [21201] [rtc::impl::SctpTransport::SctpTransport@189] Initializing SCTP transport
2022-09-01 09:17:11.426 INFO  [21202] [rtc::impl::DtlsTransport::runRecvLoop@565] DTLS handshake finished
2022-09-01 09:17:11.426 DEBUG [21201] [rtc::impl::SctpTransport::connect@371] SCTP connecting (local port=5000, remote port=5000)
2022-09-01 09:17:11.426 DEBUG [21202] [rtc::impl::SctpTransport::SctpTransport@189] Initializing SCTP transport
2022-09-01 09:17:11.427 DEBUG [21202] [rtc::impl::SctpTransport::connect@371] SCTP connecting (local port=5000, remote port=5000)
2022-09-01 09:17:11.428 DEBUG [21194] [rtc::impl::SctpTransport::processNotification@825] SCTP negotiated streams: incoming=1024, outgoing=1024
2022-09-01 09:17:11.428 DEBUG [21193] [rtc::impl::SctpTransport::processNotification@825] SCTP negotiated streams: incoming=1024, outgoing=1024
2022-09-01 09:17:11.429 INFO  [21194] [rtc::impl::SctpTransport::processNotification@830] SCTP connected
2022-09-01 09:17:11.429 INFO  [21193] [rtc::impl::SctpTransport::processNotification@830] SCTP connected
2022-09-01 09:17:11.429 INFO  [21194] [rtc::impl::PeerConnection::changeState@1151] Changed state to connected
2022-09-01 09:17:11.429 INFO  [21193] [rtc::impl::PeerConnection::changeState@1151] Changed state to connected
Peer1 State: connected
Peer2 State: connected
Peer2 Got DataChannel:  test
Peer1 Received Msg: Hello From Peer2
Peer2 Received Msg: Hello from Peer1
2022-09-01 09:17:11.469 INFO  [21198] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to completed
2022-09-01 09:17:16.010 DEBUG [21195] [rtc::impl::SctpTransport::sendReset@683] SCTP resetting stream 1
2022-09-01 09:17:16.010 INFO  [21191] [rtc::impl::PeerConnection::changeState@1151] Changed state to closed
2022-09-01 09:17:16.010 DEBUG [21193] [rtc::impl::SctpTransport::sendReset@683] SCTP resetting stream 1
2022-09-01 09:17:16.010 INFO  [21191] [rtc::impl::PeerConnection::changeState@1151] Changed state to closed
2022-09-01 09:17:16.010 DEBUG [21194] [rtc::impl::SctpTransport::shutdown@392] SCTP shutdown
2022-09-01 09:17:16.011 INFO  [21194] [rtc::impl::SctpTransport::shutdown@400] SCTP disconnected
2022-09-01 09:17:16.011 DEBUG [21194] [rtc::impl::DtlsTransport::stop@480] Stopping DTLS recv thread
2022-09-01 09:17:16.011 INFO  [21201] [rtc::impl::DtlsTransport::runRecvLoop@612] DTLS closed
2022-09-01 09:17:16.011 INFO  [21193] [rtc::impl::SctpTransport::processNotification@837] SCTP disconnected
2022-09-01 09:17:16.011 DEBUG [21194] [rtc::impl::SctpTransport::shutdown@392] SCTP shutdown
2022-09-01 09:17:16.011 INFO  [21194] [rtc::impl::SctpTransport::shutdown@400] SCTP disconnected
2022-09-01 09:17:16.011 DEBUG [21194] [rtc::impl::DtlsTransport::stop@480] Stopping DTLS recv thread
2022-09-01 09:17:16.011 INFO  [21202] [rtc::impl::DtlsTransport::runRecvLoop@612] DTLS closed
2022-09-01 09:17:16.012 DEBUG [21220] [rtc::impl::Init::doCleanup@158] Global cleanup
FATAL ERROR: Error::New napi_get_last_error_info
 1: 0xb09980 node::Abort() [node]
 2: 0xa1c235 node::FatalError(char const*, char const*) [node]
 3: 0xa1c23e  [node]
 4: 0xad139b napi_fatal_error [node]
 5: 0x7f9f71cfc070 Napi::CallbackScope::~CallbackScope() [/home/murat/js/temp/worker-thread-test/node-datachannel/build/Release/node_datachannel.node]
 6: 0x7f9f71cfc398 Napi::Error::New(napi_env__*) [/home/murat/js/temp/worker-thread-test/node-datachannel/build/Release/node_datachannel.node]
 7: 0x7f9f71ce221f  [/home/murat/js/temp/worker-thread-test/node-datachannel/build/Release/node_datachannel.node]
 8: 0x7f9f71d37875 ThreadSafeCallback::callbackFunc(Napi::Env, Napi::Function, Napi::Reference<Napi::Value>*, ThreadSafeCallback::CallbackData*) [/home/murat/js/temp/worker-thread-test/node-datachannel/build/Release/node_datachannel.node]
 9: 0xacfddc  [node]
10: 0x1563dd1 uv_run [node]
11: 0xa43dd5 node::SpinEventLoop(node::Environment*) [node]
12: 0xbd3262 node::worker::Worker::Run() [node]
13: 0xbd39f8  [node]
14: 0x7f9f8133d609  [/lib/x86_64-linux-gnu/libpthread.so.0]
15: 0x7f9f81262133 clone [/lib/x86_64-linux-gnu/libc.so.6]
Aborted (core dumped)

Could you please check it?

Test env;

// main.js
const { Worker, isMainThread, parentPort } = require('worker_threads');
if (isMainThread) {
  // This code is executed in the main thread and not in the worker.
  
  // Create the worker.
  const worker = new Worker('./worker.js');
  // Listen for messages from the worker and print them.
  worker.on('message', (msg) => { console.log(msg); });
} else {
  // This code is executed in the worker and not in the main thread.
  
  // Send a message to the main thread.
  parentPort.postMessage('Hello world!');
}

// worker.js
// eslint-disable-next-line @typescript-eslint/no-var-requires
const nodeDataChannel = require('./node-datachannel');

nodeDataChannel.initLogger('Debug');
nodeDataChannel.preload();

let dc1 = null;
let dc2 = null;

// Config options
// export interface RtcConfig {
//     iceServers: string[];
//     proxyServer?: ProxyServer;
//     enableIceTcp?: boolean;
//     portRangeBegin?: number;
//     portRangeEnd?: number;
//     maxMessageSize?: number;
//     iceTransportPolicy?: TransportPolicy;
// }
//
// "iceServers" option is an array of stun/turn server urls
// Examples;
// STUN Server Example          : stun:stun.l.google.com:19302
// TURN Server Example          : turn:USERNAME:PASSWORD@TURN_IP_OR_ADDRESS:PORT
// TURN Server Example (TCP)    : turn:USERNAME:PASSWORD@TURN_IP_OR_ADDRESS:PORT?transport=tcp
// TURN Server Example (TLS)    : turns:USERNAME:PASSWORD@TURN_IP_OR_ADDRESS:PORT

let peer1 = new nodeDataChannel.PeerConnection('Peer1', { iceServers: ['stun:stun.l.google.com:19302'] });

// Set Callbacks
peer1.onStateChange((state) => {
    console.log('Peer1 State:', state);
});
peer1.onGatheringStateChange((state) => {
    console.log('Peer1 GatheringState:', state);
});
peer1.onLocalDescription((sdp, type) => {
    console.log('Peer1 SDP:', sdp, ' Type:', type);
    peer2.setRemoteDescription(sdp, type);
});
peer1.onLocalCandidate((candidate, mid) => {
    console.log('Peer1 Candidate:', candidate);
    peer2.addRemoteCandidate(candidate, mid);
});

let peer2 = new nodeDataChannel.PeerConnection('Peer2', { iceServers: ['stun:stun.l.google.com:19302'] });

// Set Callbacks
peer2.onStateChange((state) => {
    console.log('Peer2 State:', state);
});
peer2.onGatheringStateChange((state) => {
    console.log('Peer2 GatheringState:', state);
});
peer2.onLocalDescription((sdp, type) => {
    console.log('Peer2 SDP:', sdp, ' Type:', type);
    peer1.setRemoteDescription(sdp, type);
});
peer2.onLocalCandidate((candidate, mid) => {
    console.log('Peer2 Candidate:', candidate);
    peer1.addRemoteCandidate(candidate, mid);
});
peer2.onDataChannel((dc) => {
    console.log('Peer2 Got DataChannel: ', dc.getLabel());
    dc2 = dc;
    dc2.onMessage((msg) => {
        console.log('Peer2 Received Msg:', msg);
    });
    dc2.sendMessage('Hello From Peer2');
    dc2.onClosed(() => {
        console.log('dc2 closed');
    });
});

// DataChannel Options
// export interface DataChannelInitConfig {
//     protocol?: string;
//     negotiated?: boolean;
//     id?: number;
//     ordered?: boolean;
//     maxPacketLifeTime?: number;
//     maxRetransmits?: number;
// }
dc1 = peer1.createDataChannel('test');
dc1.onOpen(() => {
    dc1.sendMessage('Hello from Peer1');
    // Binary message: Use sendMessageBinary(Buffer)
});
dc1.onMessage((msg) => {
    console.log('Peer1 Received Msg:', msg);
});
dc1.onClosed(() => {
    console.log('dc1 closed');
});

setTimeout(() => {
    dc1.close();
    dc2.close();
    peer1.close();
    peer2.close();
    nodeDataChannel.cleanup();
}, 5 * 1000);

murat-dogan avatar Sep 01 '22 06:09 murat-dogan

Hi @murat-dogan, sorry, are you expecting a test from my side ? If yes, I will do it quickly

oanguenot avatar Sep 08 '22 14:09 oanguenot

Hi No actually I am still testing. I found a solution and will release it asap

murat-dogan avatar Sep 08 '22 16:09 murat-dogan

@paullouisageneau You have commits for js callback hell :)

Could you please check https://github.com/murat-dogan/node-datachannel/pull/131 ? Any comment appreciated.

@oanguenot If possible could you please pull and test https://github.com/murat-dogan/node-datachannel/pull/131?

murat-dogan avatar Sep 09 '22 07:09 murat-dogan

@murat-dogan Sorry I didn't have time to check the issue, I'm looking into #131

paullouisageneau avatar Sep 09 '22 08:09 paullouisageneau

Hi @oanguenot ,

Did you have any chance to test v0.4.0? Is this issue still exist for you?

murat-dogan avatar Oct 27 '22 06:10 murat-dogan

I am closing this as well. If you need to please re-open it.

murat-dogan avatar Nov 02 '22 10:11 murat-dogan