search

pion / webrtc

Pure Go implementation of the WebRTC API
https://pion.ly
MIT License
13.88k stars 1.66k forks source link

Peer connection closes immediately after opening detached data channel on v4.0.0-beta.25 or newer #2909

Closed mudge closed 1 month ago

mudge commented 2 months ago

Your environment.

What did you do?

Established a WebRTC connection between Chrome on macOS and the data-channels-detach example on a Raspberry Pi Zero W using the official data-channels example page (linked to from the data-channels example). The data-channels-detach code was cross-compiled with:

$ GOOS=linux GOARCH=arm GOARM=6,hardfloat go install github.com/pion/webrtc/v4/examples/data-channels-detach@v4.0.0-beta.25

What did you expect?

On v4.0.0-beta.24, a connection is established and kept alive as per the following logs from PION_LOG_TRACE=all 

ice TRACE: 14:36:39.730154 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:59326 to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649), useCandidate: true
ice DEBUG: 14:36:39.732807 agent.go:1043: Adding a new peer-reflexive candidate: 192.168.1.220:59326 
ice TRACE: 14:36:39.737046 agent.go:895: Ping STUN from udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) to udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326)
ice TRACE: 14:36:39.740197 agent.go:948: Discarded 32 binding requests because they expired
ice TRACE: 14:36:39.743684 agent.go:461: Pinging all candidates
ice TRACE: 14:36:39.744733 agent.go:895: Ping STUN from udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) to udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326)
ice TRACE: 14:36:39.751898 agent.go:895: Ping STUN from udp4 srflx 89.241.92.122:53815 related 0.0.0.0:53815 (resolved: 89.241.92.122:53815) to udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326)
ice TRACE: 14:36:39.757868 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649)
ice TRACE: 14:36:39.763753 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) <-> udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) (remote, prio 1862270975), state: succeeded, nominated: false, nominateOnBindingSuccess: true
ice TRACE: 14:36:39.769275 agent.go:449: Set selected candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) <-> udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
ice INFO: 2024/09/26 14:36:39 Setting new connection state: Connected
pc INFO: 2024/09/26 14:36:39 ICE connection state changed: connected
dtls TRACE: 14:36:39.783210 handshaker.go:176: [handshake:client] Flight 1: Preparing
dtls TRACE: 14:36:39.787017 handshaker.go:176: [handshake:client] Flight 1: Sending
dtls TRACE: 14:36:39.790843 conn.go:416: [handshake:client] -> ClientHello (epoch: 0, seq: 0)
ice TRACE: 14:36:39.783607 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) to udp4 srflx 89.241.92.122:53815 related 0.0.0.0:53815 (resolved: 89.241.92.122:53815)
ice TRACE: 14:36:39.797064 selection.go:239: Found valid candidate pair: prio 7277816995565797376 (local, prio 1694498815) udp4 srflx 89.241.92.122:53815 related 0.0.0.0:53815 (resolved: 89.241.92.122:53815) <-> udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) (remote, prio 1862270975), state: succeeded, nominated: false, nominateOnBindingSuccess: false
ice TRACE: 14:36:39.797625 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649)
ice TRACE: 14:36:39.798082 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) <-> udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
ice TRACE: 14:36:39.798626 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:59326 to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649), useCandidate: true
ice TRACE: 14:36:39.805186 agent.go:895: Ping STUN from udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) to udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326)
dtls TRACE: 14:36:39.807521 handshaker.go:176: [handshake:client] Flight 1: Waiting
dtls TRACE: 14:36:39.813387 flight3handler.go:90: [handshake] use cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
ice TRACE: 14:36:39.830350 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649)
ice TRACE: 14:36:39.832839 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) <-> udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
ice TRACE: 14:36:39.834528 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:59326 to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649), useCandidate: true
ice TRACE: 14:36:39.837802 agent.go:895: Ping STUN from udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) to udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326)
dtls TRACE: 14:36:39.855387 handshaker.go:292: [handshake:client] Flight 1 -> Flight 5
dtls TRACE: 14:36:39.857492 handshaker.go:176: [handshake:client] Flight 5: Preparing
ice TRACE: 14:36:39.863968 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) to udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649)
ice TRACE: 14:36:39.867515 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:59649 (resolved: 192.168.1.149:59649) <-> udp4 prflx 192.168.1.220:59326 related :0 (resolved: 192.168.1.220:59326) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
dtls TRACE: 14:36:39.917501 handshaker.go:244: [handshake:client] -> changeCipherSpec (epoch: 1)
dtls TRACE: 14:36:39.919677 handshaker.go:176: [handshake:client] Flight 5: Sending
dtls TRACE: 14:36:39.921648 conn.go:416: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:36:39.922293 conn.go:416: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:36:39.925918 conn.go:416: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:36:39.928736 conn.go:416: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:36:39.933965 handshaker.go:176: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:36:39.940331 conn.go:782: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:36:39.942508 handshaker.go:292: [handshake:client] Flight 5 -> Flight 5
dtls TRACE: 14:36:39.942735 handshaker.go:176: [handshake:client] Flight 5: Finished
dtls TRACE: 14:36:39.942979 conn.go:239: Handshake Completed
pc INFO: 2024/09/26 14:36:39 peer connection state changed: connected
sctp TRACE: 14:36:39.946456 association.go:374: [0x1882b48] updated cwnd=4380 ssthresh=0 inflight=0 (INI)
sctp DEBUG: 14:36:39.946847 association.go:426: [0x1882b48] sending INIT
sctp DEBUG: 14:36:39.947013 association.go:1083: [0x1882b48] state change: 'Closed' => 'CookieWait'
sctp DEBUG: 14:36:39.947212 association.go:616: [0x1882b48] writeLoop entered
Peer Connection State has changed: connected
sctp DEBUG: 14:36:39.951512 association.go:590: [0x1882b48] readLoop entered
sctp DEBUG: 14:36:39.959617 association.go:1162: [0x1882b48] chunkInit received in state 'CookieWait'
sctp DEBUG: 14:36:39.965031 association.go:1198: [0x1882b48] use ForwardTSN (on init)
sctp DEBUG: 14:36:39.967403 association.go:1217: sending INIT ACK
ice TRACE: 14:36:39.963401 selection.go:181: Checking keepalive
sctp DEBUG: 14:36:39.968754 association.go:1239: [0x1882b48] sendZeroChecksum=false (on init)
sctp DEBUG: 14:36:39.972580 association.go:1251: [0x1882b48] chunkInitAck received in state 'CookieWait'
sctp DEBUG: 14:36:39.974364 association.go:1273: [0x1882b48] initial rwnd=5242880
sctp TRACE: 14:36:39.975706 association.go:1280: [0x1882b48] updated cwnd=4380 ssthresh=5242880 inflight=0 (INI)
sctp DEBUG: 14:36:39.976247 association.go:1294: [0x1882b48] use ForwardTSN (on initAck)
sctp DEBUG: 14:36:39.978504 association.go:1303: [0x1882b48] sendZeroChecksum=false (on initAck)
sctp DEBUG: 14:36:39.979672 association.go:452: [0x1882b48] sending COOKIE-ECHO
sctp DEBUG: 14:36:39.981459 association.go:1083: [0x1882b48] state change: 'CookieWait' => 'CookieEchoed'
sctp DEBUG: 14:36:39.990656 association.go:1350: [0x1882b48] COOKIE-ECHO received in state 'CookieEchoed'
sctp DEBUG: 14:36:39.992601 association.go:1083: [0x1882b48] state change: 'CookieEchoed' => 'Established'
sctp DEBUG: 14:36:39.997598 association.go:1393: [0x1882b48] COOKIE-ACK received in state 'Established'
sctp TRACE: 14:36:40.000120 association.go:1412: [0x1882b48] DATA: tsn=850347405 immediateSack=false len=15
sctp DEBUG: 14:36:40.001146 association.go:1536: [0x1882b48] accepted a new stream (streamIdentifier: 1)
sctp DEBUG: 14:36:40.002010 stream.go:203: [1:0x1882b48] reassemblyQueue readable=true
sctp DEBUG: 14:36:40.003157 stream.go:205: [1:0x1882b48] readNotifier.signal()
sctp DEBUG: 14:36:40.005842 stream.go:207: [1:0x1882b48] readNotifier.signal() done
sctp TRACE: 14:36:40.008097 stream.go:337: [1:0x1882b48] bufferedAmount = 4
sctp DEBUG: 14:36:40.009909 stream.go:102: [1:0x1882b48] reliability params: ordered=true type=0 value=0
New DataChannel foo 26830834
Data channel 'foo'-'26830834' open.

What happened?

With v4.0.0-beta.25, executing the exact same code results in the connection closing immediately, as per the following logs 

ice TRACE: 14:38:47.592284 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:51671 to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216), useCandidate: true
ice DEBUG: 14:38:47.594926 agent.go:1043: Adding a new peer-reflexive candidate: 192.168.1.220:51671 
ice TRACE: 14:38:47.600479 agent.go:895: Ping STUN from udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
ice TRACE: 14:38:47.604454 agent.go:948: Discarded 32 binding requests because they expired
ice TRACE: 14:38:47.607345 agent.go:461: Pinging all candidates
ice TRACE: 14:38:47.608616 agent.go:895: Ping STUN from udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
ice TRACE: 14:38:47.614065 agent.go:895: Ping STUN from udp4 srflx 89.241.92.122:48006 related 0.0.0.0:48006 (resolved: 89.241.92.122:48006) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
ice TRACE: 14:38:47.620613 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216)
ice TRACE: 14:38:47.624361 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: false, nominateOnBindingSuccess: true
ice TRACE: 14:38:47.627442 agent.go:449: Set selected candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
ice INFO: 2024/09/26 14:38:47 Setting new connection state: Connected
ice TRACE: 14:38:47.633174 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) to udp4 srflx 89.241.92.122:48006 related 0.0.0.0:48006 (resolved: 89.241.92.122:48006)
ice TRACE: 14:38:47.646238 selection.go:239: Found valid candidate pair: prio 7277816995565797376 (local, prio 1694498815) udp4 srflx 89.241.92.122:48006 related 0.0.0.0:48006 (resolved: 89.241.92.122:48006) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: false, nominateOnBindingSuccess: false
ice TRACE: 14:38:47.649273 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:51671 to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216), useCandidate: true
ice TRACE: 14:38:47.653911 agent.go:895: Ping STUN from udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
dtls TRACE: 14:38:47.644032 handshaker.go:187: [handshake:client] Flight 1: Preparing
dtls TRACE: 14:38:47.656269 handshaker.go:187: [handshake:client] Flight 1: Sending
dtls TRACE: 14:38:47.659721 conn.go:442: [handshake:client] -> ClientHello (epoch: 0, seq: 0)
pc INFO: 2024/09/26 14:38:47 ICE connection state changed: connected
ice TRACE: 14:38:47.664899 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216)
ice TRACE: 14:38:47.669660 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
dtls TRACE: 14:38:47.667079 handshaker.go:187: [handshake:client] Flight 1: Waiting
ice TRACE: 14:38:47.691613 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:51671 to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216), useCandidate: true
ice TRACE: 14:38:47.695826 agent.go:895: Ping STUN from udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
ice TRACE: 14:38:47.706376 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216)
ice TRACE: 14:38:47.708047 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
ice TRACE: 14:38:47.817890 selection.go:181: Checking keepalive
dtls TRACE: 14:38:48.675331 handshaker.go:187: [handshake:client] Flight 1: Sending
dtls TRACE: 14:38:48.675814 conn.go:442: [handshake:client] -> ClientHello (epoch: 0, seq: 0)
dtls TRACE: 14:38:48.681757 handshaker.go:187: [handshake:client] Flight 1: Waiting
dtls TRACE: 14:38:48.692185 flight3handler.go:102: [handshake] use cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
dtls TRACE: 14:38:48.730279 handshaker.go:307: [handshake:client] Flight 1 -> Flight 5
dtls TRACE: 14:38:48.731906 handshaker.go:187: [handshake:client] Flight 5: Preparing
ice TRACE: 14:38:48.768168 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:51671 to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216), useCandidate: true
ice TRACE: 14:38:48.772644 agent.go:895: Ping STUN from udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
ice TRACE: 14:38:48.788590 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216)
ice TRACE: 14:38:48.790534 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
dtls TRACE: 14:38:48.808406 handshaker.go:255: [handshake:client] -> changeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.809075 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.810198 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.810770 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.811871 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.812316 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.813953 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:48.816538 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.817542 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.817928 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.819149 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.819441 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.821613 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:48.822535 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.824610 handshaker.go:307: [handshake:client] Flight 5 -> Flight 5
dtls TRACE: 14:38:48.824994 handshaker.go:187: [handshake:client] Flight 5: Finished
dtls TRACE: 14:38:48.826620 conn.go:294: Handshake Completed
pc INFO: 2024/09/26 14:38:48 peer connection state changed: connected
sctp TRACE: 14:38:48.832965 association.go:374: [0x2082b48] updated cwnd=4380 ssthresh=0 inflight=0 (INI)
sctp DEBUG: 14:38:48.834197 association.go:426: [0x2082b48] sending INIT
sctp DEBUG: 14:38:48.836415 association.go:1083: [0x2082b48] state change: 'Closed' => 'CookieWait'
sctp DEBUG: 14:38:48.837655 association.go:616: [0x2082b48] writeLoop entered
Peer Connection State has changed: connected
sctp DEBUG: 14:38:48.841149 association.go:590: [0x2082b48] readLoop entered
dtls TRACE: 14:38:48.843821 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.845009 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.846836 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.847840 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.848212 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.849769 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.853521 handshaker.go:187: [handshake:client] Flight 5: Waiting
sctp DEBUG: 14:38:48.856403 association.go:1162: [0x2082b48] chunkInit received in state 'CookieWait'
sctp DEBUG: 14:38:48.856860 association.go:1198: [0x2082b48] use ForwardTSN (on init)
sctp DEBUG: 14:38:48.857114 association.go:1217: sending INIT ACK
sctp DEBUG: 14:38:48.858037 association.go:1239: [0x2082b48] sendZeroChecksum=false (on init)
dtls TRACE: 14:38:48.862237 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.862760 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.862991 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.863219 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.863414 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.863615 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.864902 handshaker.go:187: [handshake:client] Flight 5: Waiting
sctp DEBUG: 14:38:48.865752 association.go:1251: [0x2082b48] chunkInitAck received in state 'CookieWait'
sctp DEBUG: 14:38:48.865951 association.go:1273: [0x2082b48] initial rwnd=5242880
sctp TRACE: 14:38:48.866105 association.go:1280: [0x2082b48] updated cwnd=4380 ssthresh=5242880 inflight=0 (INI)
sctp DEBUG: 14:38:48.866253 association.go:1294: [0x2082b48] use ForwardTSN (on initAck)
sctp DEBUG: 14:38:48.866401 association.go:1303: [0x2082b48] sendZeroChecksum=false (on initAck)
sctp DEBUG: 14:38:48.866536 association.go:452: [0x2082b48] sending COOKIE-ECHO
sctp DEBUG: 14:38:48.866727 association.go:1083: [0x2082b48] state change: 'CookieWait' => 'CookieEchoed'
sctp DEBUG: 14:38:48.870418 association.go:1350: [0x2082b48] COOKIE-ECHO received in state 'CookieEchoed'
sctp DEBUG: 14:38:48.872561 association.go:1083: [0x2082b48] state change: 'CookieEchoed' => 'Established'
dtls TRACE: 14:38:48.876167 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.876669 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.877030 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.877400 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.877673 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.877900 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.880398 handshaker.go:187: [handshake:client] Flight 5: Waiting
sctp DEBUG: 14:38:48.884595 association.go:1393: [0x2082b48] COOKIE-ACK received in state 'Established'
sctp TRACE: 14:38:48.885002 association.go:1412: [0x2082b48] DATA: tsn=2864392045 immediateSack=false len=15
sctp DEBUG: 14:38:48.886676 association.go:1536: [0x2082b48] accepted a new stream (streamIdentifier: 1)
sctp DEBUG: 14:38:48.887044 stream.go:203: [1:0x2082b48] reassemblyQueue readable=true
sctp DEBUG: 14:38:48.888222 stream.go:205: [1:0x2082b48] readNotifier.signal()
sctp DEBUG: 14:38:48.888504 stream.go:207: [1:0x2082b48] readNotifier.signal() done
sctp TRACE: 14:38:48.890843 stream.go:337: [1:0x2082b48] bufferedAmount = 4
sctp DEBUG: 14:38:48.892787 stream.go:102: [1:0x2082b48] reliability params: ordered=true type=0 value=0
New DataChannel foo 35165554
Data channel 'foo'-'35165554' open.
sctp TRACE: 14:38:48.895602 association.go:2241: [0x2082b48] sending ppi=50 tsn=3718348758 ssn=0 sent=1 len=4 (true,true)
sctp TRACE: 14:38:48.896839 association.go:742: [0x2082b48] T3-rtx timer start (pt1)
dtls TRACE: 14:38:48.899603 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.901571 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.902489 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.903392 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.903663 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.903879 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.904923 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:48.912875 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.914597 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.916418 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.918660 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.920984 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.923121 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.927765 handshaker.go:187: [handshake:client] Flight 5: Waiting
sctp TRACE: 14:38:48.919351 association.go:1780: [0x2082b48] SACK: cumTSN=3718348758 a_rwnd=4718592
sctp TRACE: 14:38:48.930463 association.go:1611: [0x2082b48] SACK: measured-rtt=34.082759 srtt=34.082759 new-rto=1000.000000
sctp TRACE: 14:38:48.931172 association.go:1818: [0x2082b48] SACK: cumTSN advanced: 3718348757 -> 3718348758
sctp TRACE: 14:38:48.933700 association.go:1670: [0x2082b48] SACK: no more packet in-flight (pending=0)
sctp TRACE: 14:38:48.935280 association.go:1697: [0x2082b48] cwnd did not grow: cwnd=4380 ssthresh=5242880 acked=4 FR=false pending=0
sctp TRACE: 14:38:48.936927 stream.go:424: [1:0x2082b48] bufferedAmount = 0
dtls TRACE: 14:38:48.936288 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.940930 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.942422 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.944377 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.947037 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.948452 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.951923 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:48.988364 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:48.990496 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:48.992640 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:48.993378 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:48.995050 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:48.995451 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:48.999560 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:49.010786 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:49.012466 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:49.012758 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:49.013042 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:49.013383 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:49.013615 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:49.018017 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:49.045081 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:49.047491 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:49.050137 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:49.051985 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:49.052398 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:49.054271 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:49.057132 handshaker.go:187: [handshake:client] Flight 5: Waiting
sctp TRACE: 14:38:49.090733 association.go:2723: [0x2082b48] ack timed out (ackState: 2)
sctp DEBUG: 14:38:49.092269 association.go:864: [0x2082b48] sending SACK: SACK cumTsnAck=2864392045 arwnd=1048576 dupTsn=[]
sctp TRACE: 14:38:49.386993 association.go:1412: [0x2082b48] DATA: tsn=2864392045 immediateSack=false len=15
sctp TRACE: 14:38:49.588422 association.go:2723: [0x2082b48] ack timed out (ackState: 2)
sctp DEBUG: 14:38:49.590828 association.go:864: [0x2082b48] sending SACK: SACK cumTsnAck=2864392045 arwnd=1048576 dupTsn=[]
mdns DEBUG: 14:38:49.756464 conn.go:871: [0x2017580] got read on multi6 from [fe80::f3:a0bc:1510:afc2%wlan0]:5353
mdns DEBUG: 14:38:49.757941 conn.go:871: [0x2017580] got read on multi4 from 192.168.1.217:5353
ice TRACE: 14:38:49.770797 agent.go:1010: Inbound STUN (Request) from 192.168.1.220:51671 to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216), useCandidate: true
ice TRACE: 14:38:49.776463 agent.go:895: Ping STUN from udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) to udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671)
ice TRACE: 14:38:49.793909 selection.go:229: Inbound STUN (SuccessResponse) from udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) to udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216)
ice TRACE: 14:38:49.796776 selection.go:239: Found valid candidate pair: prio 7998392936314175487 (local, prio 2130706431) udp4 host 192.168.1.149:49216 (resolved: 192.168.1.149:49216) <-> udp4 prflx 192.168.1.220:51671 related :0 (resolved: 192.168.1.220:51671) (remote, prio 1862270975), state: succeeded, nominated: true, nominateOnBindingSuccess: true
ice TRACE: 14:38:49.820887 selection.go:181: Checking keepalive
dtls TRACE: 14:38:50.058626 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:50.060896 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:50.064129 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:50.064870 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:50.065196 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:50.069918 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:50.076161 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:50.078646 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:50.081418 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:50.084917 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:50.086911 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:50.089356 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:50.094929 handshaker.go:187: [handshake:client] Flight 5: Waiting
ice TRACE: 14:38:51.824134 selection.go:181: Checking keepalive
dtls TRACE: 14:38:52.096985 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:52.097501 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:52.098016 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:52.098397 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:52.098710 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:52.105040 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:52.116205 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:52.120145 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:52.123164 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:52.124311 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:52.126287 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:52.129280 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:52.134095 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:52.139734 conn.go:931: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 14:38:52.142477 handshaker.go:187: [handshake:client] Flight 5: Sending
dtls TRACE: 14:38:52.145457 conn.go:442: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 14:38:52.147881 conn.go:442: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 14:38:52.151827 conn.go:442: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 14:38:52.152317 conn.go:442: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 14:38:52.158136 handshaker.go:187: [handshake:client] Flight 5: Waiting
dtls TRACE: 14:38:52.167350 conn.go:912: client: <- Alert Warning: CloseNotify
pc INFO: 2024/09/26 14:38:52 Closing PeerConnection from DTLS CloseNotify
sctp DEBUG: 14:38:52.177368 association.go:612: [0x2082b48] readLoop exited EOF
sctp DEBUG: 14:38:52.178374 association.go:582: [0x2082b48] association closed
sctp DEBUG: 14:38:52.180768 association.go:583: [0x2082b48] stats nDATAs (in) : 2
sctp DEBUG: 14:38:52.181020 association.go:584: [0x2082b48] stats nSACKs (in) : 1
sctp DEBUG: 14:38:52.181209 association.go:585: [0x2082b48] stats nT3Timeouts : 0
sctp DEBUG: 14:38:52.181399 association.go:586: [0x2082b48] stats nAckTimeouts: 2
sctp DEBUG: 14:38:52.181586 association.go:587: [0x2082b48] stats nFastRetrans: 0
sctp DEBUG: 14:38:52.182340 association.go:502: [0x2082b48] closing association..
sctp DEBUG: 14:38:52.182699 association.go:523: [0x2082b48] closing association..
sctp DEBUG: 14:38:52.182895 association.go:1083: [0x2082b48] state change: 'Established' => 'Closed'
sctp DEBUG: 14:38:52.183413 association.go:509: [0x2082b48] association closed
sctp DEBUG: 14:38:52.183636 association.go:510: [0x2082b48] stats nPackets (in) : 7
sctp DEBUG: 14:38:52.183824 association.go:511: [0x2082b48] stats nPackets (out) : 7
sctp DEBUG: 14:38:52.184012 association.go:512: [0x2082b48] stats nDATAs (in) : 2
sctp DEBUG: 14:38:52.184204 association.go:513: [0x2082b48] stats nSACKs (in) : 1
sctp DEBUG: 14:38:52.184397 association.go:514: [0x2082b48] stats nSACKs (out) : 2
sctp DEBUG: 14:38:52.184725 association.go:515: [0x2082b48] stats nT3Timeouts : 0
sctp DEBUG: 14:38:52.193845 association.go:516: [0x2082b48] stats nAckTimeouts: 2
sctp DEBUG: 14:38:52.189334 association.go:653: [0x2082b48] writeLoop exited
sctp DEBUG: 14:38:52.190308 stream.go:349: [1:0x2082b48] Close: state=open
sctp DEBUG: 14:38:52.197960 association.go:517: [0x2082b48] stats nFastRetrans: 0
sctp DEBUG: 14:38:52.201172 stream.go:357: [1:0x2082b48] state change: open => closed
Datachannel closed; Exit the readloop: sending reset packet in non-established state: state=Closed
ice INFO: 2024/09/26 14:38:52 Setting new connection state: Closed
pc INFO: 2024/09/26 14:38:52 peer connection state changed: closed
Peer Connection State has changed: closed
Peer Connection has gone to closed exiting

It looks as though the handshake is retried multiple times on the newer version.

Please note this doesn't seem to occur on a more powerful device such as a Raspberry Pi 5 running the same version of Raspberry Pi OS (but 64-bit), it does not occur when using Mozilla Firefox 130.0.1 (64-bit) and it doesn't seem to affect the non-detached data-channels example.

mudge commented 2 months ago

Updated as this is reproducible using only the official data-channels-detach example and data-channels example page.