search

paullouisageneau / libjuice

JUICE is a UDP Interactive Connectivity Establishment library
Mozilla Public License 2.0
403 stars 75 forks source link

STUN Freshness Issue Leads to Disconnects #227

Closed matthewfarstad closed 8 months ago

matthewfarstad commented 8 months ago

At some point those non-STUN datagram messages appear by the thousands and then I disconnect.

16:08:55.738 <debug> (332153) websocket: received message: <offer>
16:08:55.738 <info> (332157) websocket: processing "offer" message
16:08:55.738 <info> (332157) [jason] test connecting with STUN server stun.l.google.com:19302
16:08:55.738 <info> (332157) peer: [test/jason/1] creating peer
16:08:55.739 <debug> (332157) peer table: generating ADD message for peer [test/jason/1]
16:08:55.739 <info> (332157) websocket: sending answer: <removed>
16:08:55.739 <debug> (332157) peer: [test/jason/1] gathering candidates
16:08:55.739 <trace> (332157) juice: agent.c:209: Assuming controlling mode
16:08:55.739 <debug> (332157) juice: agent.c:1067: Changing state to gathering
16:08:55.739 <debug> (332157) peer: [test/jason/1] state change: gathering
16:08:55.739 <trace> (332157) juice: conn.c:64: Creating connections registry
16:08:55.739 <trace> (332157) juice: conn_poll.c:93: Starting connections thread
16:08:55.740 <trace> (332157) juice: conn.c:136: Creating connection
16:08:55.740 <trace> (332157) juice: udp.c:145: UDP socket bound to any:49197
16:08:55.741 <trace> (332157) juice: agent.c:272: Gathered host candidate: xxx
16:08:55.741 <info> (332157) peer: [test/jason/1] gathered candidate
16:08:55.741 <trace> (332157) juice: agent.c:272: Gathered host candidate: xxx
16:08:55.741 <info> (332157) peer: [test/jason/1] gathered candidate
16:08:55.741 <trace> (332157) juice: agent.c:272: Gathered host candidate: xxx
16:08:55.741 <info> (332157) peer: [test/jason/1] gathered candidate
16:08:55.741 <debug> (332157) juice: agent.c:1067: Changing state to connecting
16:08:55.741 <debug> (332157) peer: [test/jason/1] state change: connecting
16:08:55.741 <trace> (332157) juice: agent.c:284: Starting resolver thread for servers
16:08:55.741 <debug> (332157) websocket: sending message:
16:08:55.741 <debug> (332157) websocket: sending message:
16:08:55.741 <debug> (332170) receiver: adding connection to hashmap: index=1
16:08:55.774 <debug> (332368) juice: agent.c:409: Using STUN server stun.l.google.com:19302
16:08:55.774 <trace> (332367) juice: agent.c:771: STUN entry 0: Sending request to xxxx (5 retransmissions left)
16:08:55.774 <trace> (332367) juice: agent.c:1495: Sending STUN Binding request
16:08:55.800 <debug> (332150) websocket: received message: <remote candidate>
16:08:55.800 <info> (332157) websocket: processing "candidate" message
16:08:55.800 <info> (332157) peer: [test/jason/1] adding candidate
16:08:55.800 <debug> (332150) websocket: received message: <remote candidate>
16:08:55.800 <info> (332157) websocket: processing "candidate" message
16:08:55.800 <info> (332157) peer: [test/jason/1] adding candidate
16:08:55.807 <trace> (332367) juice: agent.c:699: Received STUN datagram from xxxx
16:08:55.807 <trace> (332367) juice: agent.c:1342: Received STUN Binding success response from server
16:08:55.808 <debug> (332367) juice: agent.c:1345: STUN server binding successful
16:08:55.808 <debug> (332367) juice: agent.c:1364: Got STUN mapped address xxxx from server
16:08:55.823 <trace> (332367) juice: agent.c:771: STUN entry 1: Sending request to xxxx (5 retransmissions left)
16:08:55.824 <trace> (332367) juice: agent.c:1495: Sending STUN Binding request
16:08:55.861 <trace> (332367) juice: agent.c:699: Received STUN datagram from xxxx
16:08:55.861 <trace> (332367) juice: agent.c:1342: Received STUN Binding success response from server
16:08:55.861 <debug> (332367) juice: agent.c:1345: STUN server binding successful
16:08:55.861 <debug> (332367) juice: agent.c:1364: Got STUN mapped address xxxx from server
16:08:55.861 <info> (332367) peer: [test/jason/1] gathered candidate
16:08:55.861 <debug> (332367) juice: agent.c:2390: Candidate gathering done
16:08:55.861 <info> (332367) peer: [test/jason/1] gathering complete
16:08:55.861 <info> (332367) peer: [test/jason/1] switching state to PEER_GATHERED
16:08:55.861 <debug> (332367) peer table: triggering asynchronous work
16:08:55.861 <debug> (332157) websocket: sending message: <candidate sending removed for security>
16:08:55.861 <debug> (332149) peer table: running asynchonous work
16:08:55.861 <debug> (332149) peer table: found peer [test/jason/1] in state PEER_GATHERED
16:08:55.861 <info> (332149) peer: [test/jason/1] switching state to PEER_CONNECTING
16:08:55.862 <debug> (332157) websocket: sending message: <sdp json removed for security>
16:13:22.740 <warn> (332367) juice: .......... TRUNCATED 2149 MESSAGES ..........
16:13:22.740 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.740 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.740 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.740 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.740 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.740 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.740 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.740 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.741 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.741 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.741 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.741 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.741 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.741 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.741 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.741 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.741 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.741 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.741 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.741 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.741 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.741 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.741 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.741 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.747 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.747 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.747 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.748 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.748 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.748 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.748 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.748 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.748 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.748 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.748 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.748 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.748 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.748 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.748 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.748 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.748 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.748 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.748 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.748 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.748 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.748 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.748 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.748 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.752 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.752 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.752 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.752 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.752 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.752 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.752 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.752 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.752 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.752 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.752 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.752 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.752 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.752 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.752 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.752 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:22.752 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.752 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.752 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.752 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.758 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
16:13:22.758 <trace> (332367) juice: agent.c:2466: STUN selected entry matching incoming address
16:13:22.758 <trace> (332367) juice: agent.c:735: Received application datagram
16:13:22.758 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:22.758 <trace> (332367) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49195
... spammed hundreds of times
16:13:26.783 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:26.783 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:26.788 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:26.794 <trace> (332367) peer: [test/jason/1] received AUDIO message
16:13:26.794 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:26.794 <trace> (332367) peer: [test/jason/1] received REPAIR message
16:13:26.794 <trace> (332367) peer: [test/jason/1] received REPAIR message // audio still being sent
16:13:27.628 <debug> (332367) peer: [test/jason/1] state change: failed
16:13:27.628 <info> (332367) peer: [test/jason/1] switching state to PEER_DISCONNECTED
16:13:27.628 <debug> (332367) peer table: triggering asynchronous work
16:13:27.628 <debug> (332149) peer table: running asynchonous work
16:13:27.628 <debug> (332149) peer table: found peer [test/jason/1] in state PEER_DISCONNECTED
16:13:27.628 <debug> (332149) peer table: clearing [jason] from the hashmap
16:13:27.628 <debug> (332149) peer table: generating REMOVE message for peer [test/jason/1]
16:13:27.628 <info> (332149) peer: [test/jason/1] destroying peer
16:13:27.629 <debug> (332170) receiver: removing connection from hashmap: index=1
matthewfarstad commented 8 months ago 
16:33:00.605 <info> (383570) websocket: processing "offer" message
16:33:00.605 <info> (383570) [jason] test connecting with STUN server stun.l.google.com:19302
16:33:00.606 <info> (383570) peer: [test/jason/1] creating peer
16:33:00.606 <debug> (383570) peer: [test/jason/1] gathering candidates
16:33:00.607 <trace> (383570) juice: agent.c:209: Assuming controlling mode
16:33:00.607 <debug> (383570) juice: agent.c:1067: Changing state to gathering
16:33:00.607 <debug> (383570) peer: [test/jason/1] state change: gathering
16:33:00.607 <trace> (383570) juice: conn.c:64: Creating connections registry
16:33:00.607 <trace> (383570) juice: conn_poll.c:93: Starting connections thread
16:33:00.607 <trace> (383570) juice: conn.c:136: Creating connection
16:33:00.608 <trace> (383570) juice: udp.c:145: UDP socket bound to any:49151
16:33:00.608 <info> (383570) peer: [test/jason/1] gathered candidate
16:33:00.608 <info> (383570) peer: [test/jason/1] gathered candidate
16:33:00.608 <info> (383570) peer: [test/jason/1] gathered candidate
16:33:00.608 <debug> (383570) juice: agent.c:1067: Changing state to connecting
16:33:00.608 <debug> (383570) peer: [test/jason/1] state change: connecting
16:33:00.608 <debug> (383583) receiver: adding connection to hashmap: index=1
16:33:00.608 <trace> (383570) juice: agent.c:284: Starting resolver thread for servers
16:33:00.646 <debug> (383589) juice: agent.c:409: Using STUN server stun.l.google.com:19302
16:33:00.646 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:00.679 <trace> (383588) juice: agent.c:1342: Received STUN Binding success response from server
16:33:00.679 <debug> (383588) juice: agent.c:1345: STUN server binding successful
16:33:00.696 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:00.737 <trace> (383588) juice: agent.c:1342: Received STUN Binding success response from server
16:33:00.737 <debug> (383588) juice: agent.c:1345: STUN server binding successful
16:33:00.737 <info> (383588) peer: [test/jason/1] gathered candidate
16:33:00.737 <debug> (383588) juice: agent.c:2390: Candidate gathering done
16:33:00.737 <info> (383588) peer: [test/jason/1] gathering complete
16:33:00.737 <info> (383588) peer: [test/jason/1] switching state to PEER_GATHERED
16:33:00.737 <debug> (383588) peer table: triggering asynchronous work
16:33:00.823 <debug> (383570) juice: agent.c:2374: Connectivity timer started
16:33:00.823 <trace> (383570) juice: agent.c:502: Unfreezing 3 existing candidate pairs
16:33:00.823 <trace> (383570) juice: agent.c:506: Adding 3 candidates from remote description
16:33:00.823 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:00.861 <trace> (383588) juice: agent.c:2499: STUN entry 2 pair matching incoming address
16:33:00.861 <trace> (383588) juice: agent.c:1250: Received STUN Binding request
16:33:00.861 <debug> (383588) juice: agent.c:1270: ICE role conflict (both controlling)
16:33:00.861 <trace> (383588) juice: agent.c:1276: Switching to controlled role
16:33:00.873 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:00.892 <debug> (383588) juice: stun.c:686: Got STUN error code 487, reason "Error"
16:33:00.892 <trace> (383588) juice: agent.c:1425: Got STUN Binding error response, code=487
16:33:00.892 <trace> (383588) juice: agent.c:1457: Already switched roles to controlled as requested
16:33:00.923 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:00.960 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:00.960 <trace> (383588) juice: agent.c:1250: Received STUN Binding request
16:33:00.960 <trace> (383588) juice: agent.c:1495: Sending STUN Binding response
16:33:00.960 <trace> (383588) juice: agent.c:1333: Triggered pair check
16:33:00.972 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:00.990 <trace> (383588) juice: agent.c:1342: Received STUN Binding success response from peer
16:33:00.990 <trace> (383588) juice: agent.c:1397: Candidate pair check succeeded
16:33:00.990 <trace> (383588) juice: agent.c:956: New selected pair
16:33:00.990 <debug> (383588) juice: agent.c:1067: Changing state to connected
16:33:00.990 <debug> (383588) peer: [test/jason/1] state change: connected
16:33:00.990 <info> (383588) peer: [test/jason/1] switching state to PEER_CONNECTED
16:33:00.990 <debug> (383588) peer: [test/jason/1] sending CONNECT message
16:33:01.023 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:33:01.030 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.030 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.030 <debug> (383588) peer: [test/jason/1] received CONNECT message
16:33:01.030 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.030 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.030 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:01.037 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.037 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.037 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:01.037 <trace> (383588) juice: agent.c:1342: Received STUN Binding success response from peer
16:33:01.037 <trace> (383588) juice: agent.c:1397: Candidate pair check succeeded
16:33:01.037 <trace> (383588) juice: agent.c:956: New selected pair
16:33:01.041 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:01.042 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:01.042 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:01.042 <trace> (383588) juice: agent.c:2499: STUN entry 4 pair matching incoming address
16:33:25.611 <warn> (383588) juice: .......... TRUNCATED 2165 MESSAGES ..........
16:33:25.611 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.611 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.611 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.611 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.611 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.611 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.611 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.611 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.611 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.611 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.611 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.611 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.611 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.611 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.612 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.612 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.612 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.612 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.612 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.612 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.612 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.612 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.612 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.612 <trace> (383588) peer: [test/jason/1] received AUDIO message

16:33:25.618 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.618 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.618 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.618 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.618 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.618 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.618 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.618 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.618 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.618 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.618 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.618 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.618 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.618 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.618 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.618 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.618 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.618 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.618 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.618 <trace> (383588) peer: [test/jason/1] received REPAIR message

16:33:25.624 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.624 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.624 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.624 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.624 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.624 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.624 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.624 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.624 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.624 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.624 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.625 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.625 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.625 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.625 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.625 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.625 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.625 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.625 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.625 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.625 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.625 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.625 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.625 <trace> (383588) peer: [test/jason/1] received REPAIR message

16:33:25.629 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.629 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.629 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.629 <trace> (383588) peer: [test/jason/1] received AUDIO message

16:33:25.635 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.635 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.635 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.635 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.635 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.635 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.635 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.635 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.635 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.635 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.635 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.635 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.635 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.635 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.635 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.635 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.635 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.635 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.635 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.635 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.635 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.635 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.635 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.635 <trace> (383588) peer: [test/jason/1] received AUDIO message

16:33:25.641 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.641 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.641 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.641 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.641 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.641 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.641 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.641 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.641 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.641 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.641 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.641 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.641 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.641 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.641 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.641 <trace> (383588) peer: [test/jason/1] received REPAIR message
16:33:25.641 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.641 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.641 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.641 <trace> (383588) peer: [test/jason/1] received REPAIR message

16:33:25.646 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.646 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.646 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.646 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:33:25.646 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:33:25.646 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:33:25.646 <trace> (383588) juice: agent.c:735: Received application datagram
16:33:25.646 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:34:41.648 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:34:41.648 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:34:41.652 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:34:41.652 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:34:41.652 <trace> (383588) juice: agent.c:735: Received application datagram
16:34:41.652 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:34:41.652 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:34:41.652 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
16:34:41.652 <trace> (383588) juice: agent.c:735: Received application datagram
16:34:41.652 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:34:41.652 <trace> (383588) juice: agent.c:718: Received non-STUN datagram from 2603:6000:c906:980:f7bd:e3e7:bfea:41c3:49182
16:34:41.652 <trace> (383588) juice: agent.c:2466: STUN selected entry matching incoming address
... many seconds pass
16:35:07.501 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:35:07.506 <trace> (383588) peer: [test/jason/1] received AUDIO message
16:35:10.509 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=17/20
16:35:13.012 <warn> (383588) juice: .......... TRUNCATED 1939 MESSAGES ..........
16:35:13.012 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:13.012 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:17.739 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:17.739 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:20.508 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=17/20
16:35:22.266 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:22.267 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:26.414 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:26.414 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:30.366 <debug> (383562) peer table:
[1/1] CONNECTED test/jason/1
16:35:30.508 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=17/20
16:35:32.220 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:32.221 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:32.407 <debug> (383588) juice: agent.c:827: STUN entry 2: Consent expired for candidate pair
16:35:32.407 <debug> (383588) juice: agent.c:946: Lost connectivity
16:35:32.407 <debug> (383588) juice: agent.c:1067: Changing state to failed
16:35:32.407 <debug> (383588) peer: [test/jason/1] state change: failed
16:35:32.407 <info> (383588) peer: [test/jason/1] switching state to PEER_DISCONNECTED
16:35:32.407 <debug> (383588) peer table: triggering asynchronous work
16:35:32.407 <debug> (383562) peer table: running asynchonous work
16:35:32.407 <debug> (383562) peer table: found peer [test/jason/1] in state PEER_DISCONNECTED
16:35:32.407 <debug> (383562) peer table: clearing [jason] from the hashmap
16:35:32.407 <debug> (383562) peer table: generating REMOVE message for peer [test/jason/1]
16:35:32.407 <info> (383562) peer: [test/jason/1] destroying peer
16:35:32.407 <trace> (383562) juice: agent.c:143: Destroying agent
16:35:32.407 <trace> (383562) juice: conn.c:188: Destroying connection
16:35:32.407 <trace> (383562) juice: conn.c:112: No connection left, destroying connections registry
16:35:32.407 <trace> (383588) juice: conn_poll.c:323: Leaving connections thread
16:35:32.409 <debug> (383583) receiver: removing connection from hashmap: index=1
16:35:40.509 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=19/20
16:35:50.509 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=18/20
16:36:00.366 <debug> (383562) peer table:
16:36:00.509 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=18/20
16:36:05.672 <info> (383559) signals: got interruption signal
16:36:05.672 <error> (383559) interrupted by signal
16:36:05.672 <debug> (383559) sending disconnect to peers
16:36:05.672 <debug> (383559) terminating waspd session
16:36:05.672 <debug> (383559) orc agent: destroying instance
16:36:05.672 <debug> (383559) ipc: terminating ipc thread
16:36:05.672 <trace> (383559) ipc: [56302] sending: EXIT <>
16:36:05.673 <debug> (383572) ipc: received EXIT message
16:36:05.673 <info> (383572) ipc: exiting ipc thread
16:36:05.673 <debug> (383559) ipc: destroying ipc context
16:36:05.673 <debug> (383559) pipeline: stopping
16:36:05.673 <debug> (383582) pipeline: exiting input thread
16:36:05.675 <debug> (383583) pipeline: exiting output thread
16:36:05.675 <info> (383559) alsa input: closing device "hw:1"
16:36:05.679 <info> (383559) alsa output: closing device "hw:1"
16:36:05.686 <debug> (383559) ipc: terminating ipc thread
16:36:05.686 <trace> (383559) ipc: [44304] sending: EXIT <>
16:36:05.686 <debug> (383577) ipc: received EXIT message
16:36:05.686 <info> (383577) ipc: exiting ipc thread
16:36:05.686 <debug> (383559) ipc: destroying ipc context
16:36:05.688 <debug> (383559) dumper: destroying instance
16:36:05.688 <debug> (383559) dumper: switching to DUMPER_CLOSED
16:36:05.688 <debug> (383559) dumper: waiting dumper thread
16:36:05.688 <info> (383571) dumper: processing pending update
16:36:05.688 <debug> (383571) dumper: received exit request
16:36:05.688 <info> (383571) dumper: exiting dumper thread
16:36:05.689 <debug> (383570) websocket: failed to dequeue message
16:36:05.689 <debug> (383570) websocket: exiting background thread
16:36:05.689 <debug> (383559) peer table: removing all peers
16:36:05.689 <debug> (383561) peer table: exiting send thread
16:36:05.689 <debug> (383562) peer table: exiting work thread
16:36:05.689 <debug> (383559) websocket: failed to dequeue message
16:36:05.690 <debug> (383559) exiting from main with EXIT_FAILURE
paullouisageneau commented 8 months ago

At some point those non-STUN datagram messages appear by the thousands and then I disconnect.

Non-STUN datagrams are application datagrams that are demultiplexed out of the flow. It's expected that one line appears it the verbose log for every application packet.

16:35:13.012 <warn> (383588) juice: .......... TRUNCATED 1939 MESSAGES ..........
16:35:13.012 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:13.012 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:17.739 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:17.739 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:20.508 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=17/20
16:35:22.266 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:22.267 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:26.414 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:26.414 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:30.366 <debug> (383562) peer table:
[1/1] CONNECTED test/jason/1
16:35:30.508 <debug> (383582) pipeline: alsa_xruns=0/0 buffer_xruns=0/3 peer_msgs=17/20
16:35:32.220 <trace> (383588) juice: agent.c:838: STUN entry 2: Sending keepalive
16:35:32.221 <trace> (383588) juice: agent.c:1495: Sending STUN Binding request
16:35:32.407 <debug> (383588) juice: agent.c:827: STUN entry 2: Consent expired for candidate pair
16:35:32.407 <debug> (383588) juice: agent.c:946: Lost connectivity

The remote peer has stopped answering STUN binding requests for some time at this point, triggering the expiration and the lost connectivity event. It looks like there was no received application messages at least from 16:35:13 to 16:35:32, hinting that the connection is actually lost here. Are you sure the connection is still working?

matthewfarstad commented 8 months ago

Well at some point the audio stops flowing, but it's strange because we do initial connection fine and then 30 seconds of streaming and then all sound drops. Are we being migrated by a NAT or something? I thought ICE/STUN were supposed to handle that

paullouisageneau commented 8 months ago

So the consent freshness expiration and disconnection is probably just a symptom of a lost connection. It seems transmission worked fine for only a couple minutes in the log, I have no idea what caused the issue, it looks like IPv6 without NAT. A firewall could have unexpected behavior, or one of the peers could have changed addresses. Could it be possible for instance that one of the peers has IPv6 privacy extensions with a custom very short address lifetime?

ICE does not automatically handle network changes or failures, you have to renegotiate so new candidates are gathered and exchanged (like you would retry a TCP connection on failure).