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

Published 20 hours ago • verified publisher icon murat-dogan

terminate called after throwing an instance of 'Napi::Error'

Open murat-dogan opened this issue 1 year ago • 4 comments

While testing for Node v15 and v13 got the error below. @paullouisageneau any suggestion?

2022-09-09 14:16:43.629 DEBUG [184380] [rtc::impl::Init::doInit@120] Global initialization
2022-09-09 14:16:43.634 DEBUG [184398] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL)
2022-09-09 14:16:43.634 DEBUG [184399] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL)
2022-09-09 14:16:43.634 DEBUG [184380] [rtc::impl::IceTransport::IceTransport@58] Initializing ICE transport (libjuice)
2022-09-09 14:16:43.634 INFO  [184380] [rtc::impl::IceTransport::IceTransport@114] Using STUN server "stun.l.google.com:19302"
2022-09-09 14:16:43.634 DEBUG [184380] [rtc::impl::PeerConnection::processLocalDescription@948] Adding application to local description, mid="0"
2022-09-09 14:16:43.634 INFO  [184380] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to have-local-offer
2022-09-09 14:16:43.634 INFO  [184380] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to in-progress
2022-09-09 14:16:43.635 INFO  [184380] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to gathering
2022-09-09 14:16:43.635 INFO  [184380] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connecting
2022-09-09 14:16:43.635 INFO  [184380] [rtc::impl::PeerConnection::changeState@1151] Changed state to connecting
2022-09-09 14:16:43.636 INFO  [184405] [rtc::impl::IceTransport::LogCallback@354] juice: Using STUN server stun.l.google.com:19302
Peer1 Candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 36084 typ host
terminate called after throwing an instance of 'Napi::Error'
  what():  libdatachannel error while adding remote candidate: Got a remote candidate without remote description
Aborted (core dumped)

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

It looks like the local description callback doesn't fire. Could you please get the verbose log?

paullouisageneau avatar Sep 09 '22 13:09 paullouisageneau 

2022-09-12 11:59:38.276 DEBUG [234707] [rtc::impl::Init::doInit@120] Global initialization
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::PeerConnection::PeerConnection@59] Creating PeerConnection
2022-09-12 11:59:38.280 DEBUG [234714] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL)
2022-09-12 11:59:38.280 VERB  [234714] [rtc::impl::Certificate::Generate@239] Generating ECDSA P-256 key pair
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::PeerConnection::PeerConnection@59] Creating PeerConnection
2022-09-12 11:59:38.280 DEBUG [234715] [rtc::impl::Certificate::Generate@223] Generating certificate (OpenSSL)
2022-09-12 11:59:38.280 VERB  [234715] [rtc::impl::Certificate::Generate@239] Generating ECDSA P-256 key pair
2022-09-12 11:59:38.280 VERB  [234707] [rtc::PeerConnection::setLocalDescription@87] Setting local description, type=unspec
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::PeerConnection::initIceTransport@146] Starting ICE transport
2022-09-12 11:59:38.280 DEBUG [234707] [rtc::impl::IceTransport::IceTransport@58] Initializing ICE transport (libjuice)
2022-09-12 11:59:38.280 INFO  [234707] [rtc::impl::IceTransport::IceTransport@114] Using STUN server "stun.l.google.com:19302"
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Creating agent
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Created local description: ufrag="JyJP", pwd="/oZgV/GyF3YxY4chSIYpeN"
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Generated local SDP description: a=ice-ufrag:JyJP
a=ice-pwd:/oZgV/GyF3YxY4chSIYpeN
a=ice-options:ice2,trickle

2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Assuming controlling mode
2022-09-12 11:59:38.280 DEBUG [234707] [rtc::impl::PeerConnection::processLocalDescription@948] Adding application to local description, mid="0"
2022-09-12 11:59:38.280 VERB  [234707] [rtc::impl::PeerConnection::processLocalDescription@964] Issuing local description: v=0
o=rtc 2428683871 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:JyJP
a=ice-pwd:/oZgV/GyF3YxY4chSIYpeN
a=ice-options:ice2,trickle
a=fingerprint:sha-256 7B:40:B9:9B:26:B6:61:D0:E2:DF:65:FA:DF:C8:2C:FF:F9:4F:6D:9F:C7:11:7E:F6:05:FD:B7:AA:0C:B5:A3:30
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-09-12 11:59:38.280 INFO  [234707] [rtc::impl::PeerConnection::changeSignalingState@1182] Changed signaling state to have-local-offer
2022-09-12 11:59:38.281 INFO  [234707] [rtc::impl::PeerConnection::changeGatheringState@1169] Changed gathering state to in-progress
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Gathering candidates
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Creating connections registry
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Starting connections thread
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Creating connection
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: UDP socket bound to any:49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Interrupting connections thread
2022-09-12 11:59:38.281 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Entering poll on 1 sockets for 0 ms
2022-09-12 11:59:38.281 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Leaving poll
2022-09-12 11:59:38.281 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Bookkeeping...
2022-09-12 11:59:38.281 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Entering poll on 1 sockets for 10000 ms
2022-09-12 11:59:38.281 INFO  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to gathering
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Adding 5 local host candidates
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Gathered host candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::parse@100] Parsing candidate: 1 1 UDP 2122317823 10.0.0.93 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::PeerConnection::processLocalCandidate@1003] Issuing local candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::resolve@144] Resolving candidate (mode=simple): 10.0.0.93 49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::resolve@179] Resolved candidate: 10.0.0.93 49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Gathered host candidate: a=candidate:2 1 UDP 2122317567 172.19.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::parse@100] Parsing candidate: 2 1 UDP 2122317567 172.19.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::PeerConnection::processLocalCandidate@1003] Issuing local candidate: a=candidate:2 1 UDP 2122317567 172.19.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::resolve@144] Resolving candidate (mode=simple): 172.19.0.1 49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::resolve@179] Resolved candidate: 172.19.0.1 49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Gathered host candidate: a=candidate:3 1 UDP 2122317311 172.18.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::parse@100] Parsing candidate: 3 1 UDP 2122317311 172.18.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::PeerConnection::processLocalCandidate@1003] Issuing local candidate: a=candidate:3 1 UDP 2122317311 172.18.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::resolve@144] Resolving candidate (mode=simple): 172.18.0.1 49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::resolve@179] Resolved candidate: 172.18.0.1 49108
2022-09-12 11:59:38.281 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Gathered host candidate: a=candidate:4 1 UDP 2122317055 172.20.0.1 49108 typ host
2022-09-12 11:59:38.281 VERB  [234707] [rtc::Candidate::parse@100] Parsing candidate: 4 1 UDP 2122317055 172.20.0.1 49108 typ host
2022-09-12 11:59:38.282 VERB  [234707] [rtc::impl::PeerConnection::processLocalCandidate@1003] Issuing local candidate: a=candidate:4 1 UDP 2122317055 172.20.0.1 49108 typ host
2022-09-12 11:59:38.282 VERB  [234707] [rtc::Candidate::resolve@144] Resolving candidate (mode=simple): 172.20.0.1 49108
2022-09-12 11:59:38.282 VERB  [234707] [rtc::Candidate::resolve@179] Resolved candidate: 172.20.0.1 49108
2022-09-12 11:59:38.282 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Gathered host candidate: a=candidate:5 1 UDP 2122316799 172.21.0.1 49108 typ host
2022-09-12 11:59:38.282 VERB  [234707] [rtc::Candidate::parse@100] Parsing candidate: 5 1 UDP 2122316799 172.21.0.1 49108 typ host
2022-09-12 11:59:38.282 VERB  [234707] [rtc::impl::PeerConnection::processLocalCandidate@1003] Issuing local candidate: a=candidate:5 1 UDP 2122316799 172.21.0.1 49108 typ host
2022-09-12 11:59:38.282 VERB  [234707] [rtc::Candidate::resolve@144] Resolving candidate (mode=simple): 172.21.0.1 49108
2022-09-12 11:59:38.282 VERB  [234707] [rtc::Candidate::resolve@179] Resolved candidate: 172.21.0.1 49108
2022-09-12 11:59:38.282 INFO  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Changing state to connecting
2022-09-12 11:59:38.282 INFO  [234707] [rtc::impl::PeerConnection::changeState@1151] Changed state to connecting
2022-09-12 11:59:38.282 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Interrupting connections thread
2022-09-12 11:59:38.282 VERB  [234707] [rtc::impl::IceTransport::LogCallback@354] juice: Starting resolver thread for servers
2022-09-12 11:59:38.282 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Leaving poll
2022-09-12 11:59:38.282 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Bookkeeping...
2022-09-12 11:59:38.282 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Entering poll on 1 sockets for 10000 ms
2022-09-12 11:59:38.283 INFO  [234721] [rtc::impl::IceTransport::LogCallback@354] juice: Using STUN server stun.l.google.com:19302
2022-09-12 11:59:38.283 VERB  [234721] [rtc::impl::IceTransport::LogCallback@354] juice: Registering STUN entry 0 for server request
2022-09-12 11:59:38.283 VERB  [234721] [rtc::impl::IceTransport::LogCallback@354] juice: Registering STUN entry 1 for server request
2022-09-12 11:59:38.283 VERB  [234721] [rtc::impl::IceTransport::LogCallback@354] juice: Updating gathering status
2022-09-12 11:59:38.283 VERB  [234721] [rtc::impl::IceTransport::LogCallback@354] juice: STUN server or relay entry 0 is still pending
2022-09-12 11:59:38.283 VERB  [234721] [rtc::impl::IceTransport::LogCallback@354] juice: Interrupting connections thread
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Leaving poll
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Bookkeeping...
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: STUN entry 0: Sending request to 108.177.126.127:19302 (5 retransmissions left)
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Sending STUN Binding request
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Writing STUN message, class=0x0, method=0x1
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Writing STUN attribute type 0x8022, length=8
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Writing STUN attribute type 0x8028, length=4
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Sending datagram, size=40
2022-09-12 11:59:38.283 VERB  [234720] [rtc::impl::IceTransport::LogCallback@354] juice: Entering poll on 1 sockets for 50 ms
Peer1 Candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 49108 typ host
2022-09-12 11:59:38.287 VERB  [234707] [rtc::Candidate::parse@100] Parsing candidate: 1 1 UDP 2122317823 10.0.0.93 49108 typ host
2022-09-12 11:59:38.287 VERB  [234707] [rtc::PeerConnection::addRemoteCandidate@248] Adding remote candidate: a=candidate:1 1 UDP 2122317823 10.0.0.93 49108 typ host
terminate called after throwing an instance of 'Napi::Error'
  what():  libdatachannel error while adding remote candidate: Got a remote candidate without remote description
Aborted (core dumped)

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

Indeed, the local description callback should be called somewhere after Issuing local description, and it looks like it's never called.

Is it really specific to node 13 and 15?

paullouisageneau avatar Sep 13 '22 06:09 paullouisageneau

Yes, it is specific to node v13 and 15.

Actually, all callbacks are getting called. There is a problem with the queuing of the callbacks. If I ignore first candidate cb, then everything is fine.

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