Zitifiying webrtc golang - net.ListenUDP?

41

Ziti controller logs when publisher fails:

ziti-controller-1  | [1337.103]    INFO ziti/controller/network.(*Network).fault: {circuitId=[pxEvhtM9n] routerId=[VApce5mo2j]} sent unroute for circuit to router in response to forwarding fault
ziti-controller-1  | [1352.104]    INFO ziti/controller/network.(*Network).fault: network fault processing for [1] circuits

router:

ziti-edge-router-1  | [ 373.752]   ERROR ziti/router/xgress_common.(*XgressConn).WritePayload: {error=[crypto failed]} crypto failed on msg of size=69, headers=map[]
ziti-edge-router-1  | [ 373.752] WARNING ziti/router/xgress.(*Xgress).tx [{c/L0UdlPJDa|@/bX2o}<Terminator>]: {circuitId=[L0UdlPJDa] seq=[20548] origin=[Initiator]} write failed (crypto failed), closing xgress
ziti-edge-router-1  | [ 373.752] WARNING ziti/router/xgress.(*Xgress).rx [{c/L0UdlPJDa|@/bX2o}<Terminator>]: read failed (read udp 12.34.56.6:41132->12.34.56.78:3478: use of closed network connection)
ziti-edge-router-1  | [ 373.752]   ERROR ziti/router/handler_xgress.(*receiveHandler).HandleXgressReceive [{c/L0UdlPJDa|@/xnnY}<Initiator>]: {circuitId=[L0UdlPJDa] seq=[20553] error=[cannot forward payload, no destination for circuit=L0UdlPJDa src=xnnY dst=bX2o] origin=[Initiator]} unable to forward payload
ziti-edge-router-1  | [ 375.018] WARNING ziti/router/forwarder.(*Faulter).run: {ctrlId=[ziti-controller] circuitCount=[1]} reported forwarding faults

No, it happens at random.

Heres relevant livekit logs:

livekit-server-1  | 2024-12-18T14:55:17.881Z	INFO	countsincelast 394, samples required: 1
livekit-server-1  | 2024-12-18T14:55:17.896Z	DEBUG	livekit.sub	sfu/downtrack.go:2090	forwarded key frame	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "layer": 0, "rtpsn": 23177, "rtpts": 742018912}
livekit-server-1  | 2024-12-18T14:55:17.896Z	DEBUG	livekit.sub	sfu/downtrack.go:2090	forwarded key frame	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "layer": 0, "rtpsn": 23187, "rtpts": 742021911}
livekit-server-1  | 2024-12-18T14:55:18.381Z	INFO	countsincelast 5, samples required: 1
livekit-server-1  | 2024-12-18T14:55:18.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:18.880Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:18.880Z	INFO	goroutine 458 [running]:
livekit-server-1  | runtime/debug.Stack()
livekit-server-1  | 	/usr/local/go/src/runtime/debug/stack.go:24 +0x5e
livekit-server-1  | github.com/livekit/livekit-server/pkg/sfu.(*StreamTrackerManager).AddTracker.func1(0x0)
livekit-server-1  | 	/livekit/pkg/sfu/streamtrackermanager.go:216 +0x2e
livekit-server-1  | github.com/livekit/livekit-server/pkg/sfu/streamtracker.(*StreamTracker).maybeNotifyStatus(0xc000317380)
livekit-server-1  | 	/livekit/pkg/sfu/streamtracker/streamtracker.go:117 +0x75
livekit-server-1  | github.com/livekit/livekit-server/pkg/sfu/streamtracker.(*StreamTracker).updateStatus(0xc000317380)
livekit-server-1  | 	/livekit/pkg/sfu/streamtracker/streamtracker.go:289 +0x71
livekit-server-1  | github.com/livekit/livekit-server/pkg/sfu/streamtracker.(*StreamTracker).worker(0xc000317380, 0x1)
livekit-server-1  | 	/livekit/pkg/sfu/streamtracker/streamtracker.go:268 +0x2d0
livekit-server-1  | created by github.com/livekit/livekit-server/pkg/sfu/streamtracker.(*StreamTracker).Observe in goroutine 382
livekit-server-1  | 	/livekit/pkg/sfu/streamtracker/streamtracker.go:211 +0x125
livekit-server-1  | 2024-12-18T14:55:18.880Z	DEBUG	livekit.pub	sfu/streamtrackermanager.go:217	stream tracker status changed	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "mime": "video/h264", "layer": 0, "status": "stopped"}
livekit-server-1  | 2024-12-18T14:55:18.881Z	DEBUG	livekit.pub	sfu/streamtrackermanager.go:512	available layers changed - layer gone	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "mime": "video/h264", "removed": 0, "availableLayers": []}
livekit-server-1  | 2024-12-18T14:55:18.881Z	DEBUG	livekit.sub	sfu/forwarder.go:1474	stream allocation: optimal	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "allocation": {"PauseReason": "FEED_DRY", "IsDeficient": false, "BandwidthRquested": 0, "BandwidthDelta": -5494585, "BandwidthNeeded": 0, "Bitrates": [[0,0,0,0],[0,0,0,0],[0,0,0,0]], "TargetLayer": {"Spatial":0,"Temporal":0}, "RequestLayerSpatial": 0, "MaxLayer": {"Spatial":0,"Temporal":3}, "DistanceToDesired": 0}}
livekit-server-1  | 2024-12-18T14:55:19.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:19.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:19.879Z	DEBUG	livekit.pub	rtc/dynacastquality.go:140	notifying quality change	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "mime": "video/H264", "maxSubscriberQuality": {"PA_GeQXnWKmJw5P:1734533709881202554":2}, "maxSubscriberNodeQuality": {}, "maxSubscribedQuality": "HIGH", "force": true}
livekit-server-1  | 2024-12-18T14:55:19.880Z	DEBUG	livekit.pub	rtc/dynacastmanager.go:198	processing quality change	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "force": false, "committedMaxSubscribedQuality": {"video/H264":2}, "maxSubscribedQuality": {"video/H264":2}}
livekit-server-1  | 2024-12-18T14:55:19.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:19.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:20.037Z	DEBUG	livekit.sub	connectionquality/scorer.go:528	updating maxPPS	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "direction": "down", "expected": 2860, "duration": 4.070662368, "pps": 702.5883606763429}
livekit-server-1  | 2024-12-18T14:55:20.380Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:20.380Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:20.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:20.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:21.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:21.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:21.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:21.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:22.380Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:22.380Z	INFO	is stream tracker packet
livekit-server-1  | 	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:22.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:22.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:23.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:23.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:23.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:24.380Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:24.380Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:24.880Z	DEBUG	livekit.pub	connectionquality/scorer.go:443	quality drop	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "mime": "video/h264", "direction": "up", "reason": "dry", "prevScore": 95.10596526236264, "prevQuality": "EXCELLENT", "prevStat": {"startedAt": "2024-12-18T14:55:14.879Z", "duration": "5.000482724s", "packetsExpected": 2257, "packetsLost": 6, "packetsMissing": 0, "packetsOutOfOrder": 1, "bytes": 1925299, "rttMax": 3, "jitterMax": 113125.70772133033, "lastRTCPAt": "2024-12-18T14:55:17.527Z"}, "score": 20, "quality": "LOST", "stat": {"startedAt": "2024-12-18T14:55:19.879Z", "duration": "5.00030972s", "packetsExpected": 0, "packetsLost": 0, "packetsMissing": 0, "packetsOutOfOrder": 0, "bytes": 0, "rttMax": 0, "jitterMax": 0, "lastRTCPAt": "2024-12-18T14:55:17.527Z"}, "packetLossWeight": 0, "maxPPS": 776.7253330211165, "expectedBits": 0, "expectedDistance": 1.0000000000000002}
livekit-server-1  | 2024-12-18T14:55:24.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:23.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:24.881Z2024-12-18T14:55:25.380Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:25.380Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:25.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:25.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:26.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:26.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:26.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:26.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:27.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:27.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:27.881Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:27.881Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:28.382Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:28.382Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:28.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:28.880Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:29.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:29.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:29.693Z	DEBUG	livekit.transport	rtc/transport.go:626	ice connection state change	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "transport": "PUBLISHER", "state": "disconnected"}
livekit-server-1  | 2024-12-18T14:55:29.694Z	DEBUG	livekit.transport	rtc/transport.go:645	peer connection state change	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "transport": "PUBLISHER", "state": "disconnected"}
livekit-server-1  | 2024-12-18T14:55:29.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:29.880Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:30.380Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:30.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:30.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:30.880Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:31.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:31.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:31.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:31.880Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:32.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:32.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:32.880Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:32.880Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:33.381Z	INFO	countsincelast 0, samples required: 1
livekit-server-1  | 2024-12-18T14:55:33.381Z	INFO	is stream tracker packet
livekit-server-1  | 2024-12-18T14:55:33.695Z	DEBUG	livekit.transport	rtc/transport.go:626	ice connection state change	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "transport": "PUBLISHER", "state": "failed"}
livekit-server-1  | 2024-12-18T14:55:33.695Z	DEBUG	livekit.transport	rtc/transport.go:645	peer connection state change	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "transport": "PUBLISHER", "state": "failed"}
livekit-server-1  | 2024-12-18T14:55:33.695Z	DEBUG	livekit.transport	rtc/transport.go:618	short ICE connection	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "transport": "PUBLISHER", "error": "no selected pair", "errorVerbose": "no selected pair\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).getSelectedPair\n\t/livekit/pkg/rtc/transport.go:573\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).handleConnectionFailed\n\t/livekit/pkg/rtc/transport.go:617\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).onPeerConnectionStateChange\n\t/livekit/pkg/rtc/transport.go:657\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1695", "pair": "<nil>", "duration": "24.009570328s"}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit.transport	rtc/transportmanager.go:512	ignoring prefer candidate check by ICE failure because signal connection interrupted	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "lastSignalSince": "23.844113032s", "signalValid": true}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit	rtc/participant_signal.go:317	closing signal connection	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "reason": "TRANSPORT_FAILURE", "connID": "CO_SKUkaq9X7RxP"}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit	routing/signal.go:136	signal stream closed	{"room": "testroom", "reqNodeID": "ND_TzEFE3dQqK8g", "participant": "publisher", "connID": "CO_SKUkaq9X7RxP", "error": null}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit	service/rtcservice.go:335	nothing to read from response source	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "connID": "CO_SKUkaq9X7RxP"}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit	service/signal.go:175	signal stream closed	{"room": "testroom", "participant": "publisher", "connID": "CO_SKUkaq9X7RxP", "error": "stream closed"}
livekit-server-1  | {"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "valid": false}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit	service/rtcservice.go:269	finishing WS connection	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "connID": "CO_SKUkaq9X7RxP", "closedByClient": true}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit	service/roommanager.go:616	RTC session finishing	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "connID": "CO_SKUkaq9X7RxP"}
livekit-server-1  | 2024-12-18T14:55:33.729Z	DEBUG	livekit	routing/signal.go:100	starting signal connection	{"room": "testroom", "reqNodeID": "ND_TzEFE3dQqK8g", "participant": "publisher", "connID": "CO_vhCVVKxrgiS5"}
livekit-server-1  | ce source track was removed	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe"}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit	service/rtcservice.go:306	new client WS connected	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "remote": false, "connID": "CO_vhCVVKxrgiS5", "reconnect": true, "reconnectReason": "RR_UNKNOWN", "adaptiveStream": false, "selectedNodeID": "ND_TzEFE3dQqK8g", "nodeSelectionReason": ""}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.sub	sfu/downtrack.go:1015	close down track	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "flushBlankFrame": true}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.sub	sfu/forwarder.go:446	setting forwarder mute	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "subscriber", "pID": "PA_GeQXnWKmJw5P", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "muted": true}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit	rtc/participant.go:1432	updating participant state	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "state": "DISCONNECTED"}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit	service/roommanager.go:616	RTC session finishing	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "connID": "CO_vhCVVKxrgiS5"}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit	routing/signal.go:136	signal stream closed	{"room": "testroom", "reqNodeID": "ND_TzEFE3dQqK8g", "participant": "publisher", "connID": "CO_vhCVVKxrgiS5", "error": null}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit	service/rtcservice.go:335	nothing to read from response source	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "remote": false, "connID": "CO_vhCVVKxrgiS5"}
livekit-server-1  | 2024-12-18T14:55:33.696Z	DEBUG	livekit.transport	rtc/transportmanager.go:718	signal source valid	2024-12-18T14:55:33.739Z	INFO	livekit	service/roommanager.go:313	resuming RTC session	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "nodeID": "ND_TzEFE3dQqK8g", "reason": "RR_UNKNOWN", "numParticipants": 2}
livekit-server-1  | 2024-12-18T14:55:33.739Z	INFO	livekit	service/roommanager.go:821	created TURN password	{"username": "NRTcB5ERFJUZBR1RfKIo4jN8Obp5gSO0ozmqIatgOC", "password": "m02Anx0lbe0AzaVTQsG4lhxyZvju8vYqcm5rA4jKSkZ"}
livekit-server-1  | 2024-12-18T14:55:33.739Z	DEBUG	livekit.transport	rtc/transportmanager.go:718	signal source valid	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "valid": true}
livekit-server-1  | 2024-12-18T14:55:33.739Z	WARN	livekit.transport	rtc/transport.go:1294	error handling event	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "transport": "SUBSCRIBER", "event": "PCTransport:Event{signal: ICE_RESTART, data: <nil>}", "error": "create offer failed: ICEAgent does not exist: unable to restart ICETransport", "errorVerbose": "ICEAgent does not exist: unable to restart ICETransport\ncreate offer failed\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).createAndSendOffer\n\t/livekit/pkg/rtc/transport.go:1544\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).doICERestart\n\t/livekit/pkg/rtc/transport.go:1799\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).handleICERestart\n\t/livekit/pkg/rtc/transport.go:1836\ngithub.com/livekit/livekit-server/pkg/rtc.(*PCTransport).postEvent.func1\n\t/livekit/pkg/rtc/transport.go:1290\ngithub.com/livekit/livekit-server/pkg/utils.typedQueueOp[...].run\n\t/livekit/pkg/utils/opsqueue.go:53\ngithub.com/livekit/livekit-server/pkg/utils.(*opsQueueBase[...]).process\n\t/livekit/pkg/utils/opsqueue.go:154\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1695"}
livekit-server-1  | 2024-12-18T14:55:33.739Z	DEBUG	livekit	rtc/participant_signal.go:317	closing signal connection	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "reason": "FULL_RECONNECT_NEGOTIATE_FAILED", "connID": "CO_vhCVVKxrgiS5"}
livekit-server-1  | 2024-12-18T14:55:33.739Z	INFO	livekit	rtc/participant.go:874	participant closing	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "sendLeave": false, "reason": "NEGOTIATE_FAILED", "isExpectedToResume": false}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.pub	rtc/mediatrackreceiver.go:279	clearing all receivers	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.pub	rtc/mediatrackreceiver.go:527	removing all subscribers for mime	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "mime": "video/H264"}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.pub	rtc/mediatracksubscriptions.go:328	removing subscriber	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "subscriberID": "PA_GeQXnWKmJw5P", "isExpectedToResume": false}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.pub	rtc/participant.go:2207	track unpublished	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "track": {"sid": "TR_VCq9Gcy2E6naEe", "type": 1, "width": 1640, "height": 900, "source": 1, "layers": [{"quality": 2, "width": 1640, "height": 900}], "mimeType": "video/H264", "codecs": [{"cid": "TR_6HfPcSQYyqZ8", "layers": [{"quality": 2, "width": 1640, "height": 900}]}], "stream": "camera", "version": {"unixMicro": 1734533709878510}}}
livekit-server-1  | 2024-12-18T14:55:33.740Z	DEBUG	livekit.sub	rtc/subscriptionmanager.go:951	unsubscribing from track sin2024-12-18T14:55:33.741Z	DEBUG	livekit	service/rtcservice.go:269	finishing WS connection	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "remote": false, "connID": "CO_vhCVVKxrgiS5", "closedByClient": true}
livekit-server-1  | 2024-12-18T14:55:33.741Z	DEBUG	livekit	service/signal.go:175	signal stream closed	{"room": "testroom", "participant": "publisher", "connID": "CO_vhCVVKxrgiS5", "error": "stream closed"}
livekit-server-1  | 2024-12-18T14:55:33.741Z	INFO	bufferclose goroutine 609 [running]:
livekit-server-1  | runtime/debug.Stack()
livekit-server-1  | 	/usr/local/go/src/runtime/debug/stack.go:24 +0x5e
livekit-server-1  | github.com/livekit/livekit-server/pkg/sfu/buffer.(*Buffer).Close.func1()
livekit-server-1  | 	/livekit/pkg/sfu/buffer/buffer.go:477 +0x25
livekit-server-1  | sync.(*Once).doSlow(0x10?, 0xc001a80008?)
livekit-server-1  | 	/usr/local/go/src/sync/once.go:74 +0xc2
livekit-server-1  | sync.(*Once).Do(...)
livekit-server-1  | 	/usr/local/go/src/sync/once.go:65
livekit-server-1  | github.com/livekit/livekit-server/pkg/sfu/buffer.(*Buffer).Close(0xc001552488)
livekit-server-1  | 	/livekit/pkg/sfu/buffer/buffer.go:476 +0x8c
livekit-server-1  | github.com/pion/srtp/v2.(*ReadStreamSRTP).Close(0xc0012ea2a0)
livekit-server-1  | 	/go/pkg/mod/github.com/pion/srtp/v2@v2.0.18/stream_srtp.go:123 +0xa8
livekit-server-1  | github.com/pion/webrtc/v3.(*RTPReceiver).Stop(0xc0017c65a0)
livekit-server-1  | 	/go/pkg/mod/github.com/pion/webrtc/v3@v3.2.40/rtpreceiver.go:328 +0x2ab
livekit-server-1  | github.com/pion/webrtc/v3.(*RTPTransceiver).Stop(0xc001560280)
livekit-server-1  | 	/go/pkg/mod/github.com/pion/webrtc/v3@v3.2.40/rtptransceiver.go:162 +0xe5
livekit-server-1  | github.com/pion/webrtc/v3.(*PeerConnection).Close(0xc001982248)
livekit-server-1  | 	/go/pkg/mod/github.com/pion/webrtc/v3@v3.2.40/peerconnection.go:2072 +0x191
livekit-server-1  | github.com/livekit/livekit-server/pkg/rtc.(*PCTransport).Close(0xc001980008)
livekit-server-1  | 	/livekit/pkg/rtc/transport.go:973 +0x9c
livekit-server-1  | github.com/livekit/livekit-server/pkg/rtc.(*TransportManager).Close(0xc00167e008)
livekit-server-1  | 	/livekit/pkg/rtc/transportmanager.go:182 +0x25
livekit-server-1  | github.com/livekit/livekit-server/pkg/rtc.(*ParticipantImpl).Close.func1()
livekit-server-1  | 	/livekit/pkg/rtc/participant.go:915 +0x38
livekit-server-1  | created by github.com/livekit/livekit-server/pkg/rtc.(*ParticipantImpl).Close in goroutine 337
livekit-server-1  | 	/livekit/pkg/rtc/participant.go:913 +0x34a
livekit-server-1  | 2024-12-18T14:55:33.741Z	DEBUG	livekit.pub.sfu	buffer/buffer.go:482	rtp stats	{"room": "testroom", "roomID": "RM_74vbWYQxoG7y", "participant": "publisher", "pID": "PA_GTAeBEDNAq4M", "remote": false, "trackID": "TR_VCq9Gcy2E6naEe", "relayed": false, "mime": "video/h264", "layer": 0, "ssrc": 1668101941, "direction": "upstream", "stats": {"base": {"startTime": "2024-12-18T14:55:09.880Z", "endTime": "2024-12-18T14:55:33.741Z", "firstTime": "2024-12-18T14:54:58.831Z", "firstTimeAdjustment": "11.046747133s", "highestTime": "2024-12-18T14:55:17.896Z", "bytes": 5319109, "headerBytes": 73608, "packetsDuplicate": 0, "bytesDuplicate": 0, "headerBytesDuplicate": 0, "packetsPadding": 0, "bytesPadding": 0, "headerBytesPadding": 0, "packetsOutOfOrder": 1, "packetsLost": 6, "frames": 588, "jitter": 3304.3544435352105, "maxJitter": 10231.48834851043, "gapHistogram": "[7:1]", "nacks": 0, "nackAcks": 0, "nackMisses": 0, "nackRepeated": 0, "plis": 1, "lastPli": "2024-12-18T14:55:10.037Z", "layerLockPlis": 0, "lastLayerLockPli": "0001-01-01T00:00:00.000Z", "firs": 0, "lastFir": "0001-01-01T00:00:00.000Z", "keyFrames": 552, "lastKeyFrame": "2024-12-18T14:55:17.896Z", "rtt": 3, "maxRtt": 3, "srFirst": {"NTPTimestamp": "2024-12-18T14:55:10.526Z", "RTPTimestamp": 740405733, "RTPTimestampExt": 740405733, "At": "2024-12-18T14:55:10.527Z", "AtAdjusted": "2024-12-18T14:55:10.527Z"}, "srNewest": {"NTPTimestamp": "2024-12-18T14:55:17.527Z", "RTPTimestamp": 741938170, "RTPTimestampExt": 741938170, "At": "2024-12-18T14:55:17.527Z", "AtAdjusted": "2024-12-18T14:55:17.527Z"}}, "extStartSN": 17048, "extHighestSN": 23187, "extStartTS": 740255500, "extHighestTS": 742021911, "propagationDelay": "688.436µs", "longTermDeltaPropagationDelay": "171.998µs"}}
livekit-server-1  | 2024-12-18T14:55:33.741Z	INFO	sfubuffer closed
livekit-server-1  | 2024-12-18T14:55:33.741Z	INFO	Did the buffer eoffed?

The publisher failure happens when: countsincelast 0, samples required: 1 starts to get printed. it eof's later.

42

Hi @CarlosHleb, just wanted to let you know that the holiday season is starting for me. Your issue seems like it will be difficult to debug from my side as I'm not entirely sure what the issue actually is. Is the repository in a state where i can "just run it" and expect it to work? If so, I could try to take a look at this as time permits. I just wanted to drop you a note, I've not forgotten about your issue, it jsut looks like a difficult one to debug on my end, but I'll keep trying as time permits.

Cheers

43

Happy hollydays!

It should.

44

Update:

So it looks like the failures happen less often if i reduce the frame rate.

10 fps:
1) 6 minutes
2) didnt fail, stopped after 12 minutes 
3) 4 minutes

30 fps:
1) 1 minute
2) 20 seconds
3) 1 minute

60 fps:
1) 2 minutes
2) 2 minutes
3) 40 seconds

from the publisher side these are the logs that happen during the failure.

publisher-app-1  | 2025-01-08T13:22:50.345Z     INFO    pion-ice/candidate_base.go:335  dst adddrr12.12.12.12:59346
publisher-app-1  | DEBU[0295] writing 121 bytes                             chSeq=-1 connId=6 edgeSeq=6010 type=EdgeDataType
publisher-app-1  | DEBU[0295] received 12 bytes (msg type: 60785)           chSeq=564 connId=6 edgeSeq=51 type=EdgeStateClosedType
publisher-app-1  | DEBU[0295] received ConnState_CLOSED message, closing connection  connId=6 marker=JVZ1tqBX
publisher-app-1  | DEBU[0295] close: begin                                  connId=6 marker=JVZ1tqBX
publisher-app-1  | DEBU[0295] close: end                                    connId=6 marker=JVZ1tqBX
publisher-app-1  | turnc DEBUG: 13:22:50.347394 client.go:181: Failed to read: EOF. Exiting loop
publisher-app-1  | 2025-01-08T13:22:50.386Z     INFO    publisher/main.go:290   9051
publisher-app-1  | 2025-01-08T13:22:50.386Z     INFO    pion-ice/candidate_base.go:335  dst adddrr12.12.12.12:59346
publisher-app-1  | ice INFO: 2025/01/08 13:22:50 Failed to send packet: calling Write() after CloseWrite()

I keep comming back to this ziti edge router error:

ziti-edge-router-1  | [7471.082]   ERROR ziti/router/xgress_common.(*XgressConn).WritePayload: {error=[crypto failed]} crypto failed on msg of size=1237, headers=map[]
ziti-edge-router-1  | [7471.082] WARNING ziti/router/xgress.(*Xgress).tx.func3 [{c/bkeKilRaP|@/3EDr}<Terminator>]: {circuitId=[bkeKilRaP] seq=[83186] origin=[Initiator]} write failed (crypto failed), closing xgress
ziti-edge-router-1  | [7471.083] WARNING ziti/router/xgress.(*Xgress).rx [{c/bkeKilRaP|@/3EDr}<Terminator>]: read failed (read udp 12.12.12.2:58480->12.12.12.12:3478: use of closed network connection)
ziti-edge-router-1  | [7471.083]    INFO ziti/router/xgress.(*Xgress).flushSendThenClose.func1 [{c/bkeKilRaP|@/3EDr}<Terminator>]: sending end of circuit payload

crypto failed - could this be the reason ziti sends to publisher Constate_CLOSED?

45

More interesting logs:

livekit server:

livekit-server-1  | 2025-01-08T13:56:38.769Z    INFO    countsincelasts 23, samples required:  1
livekit-server-1  | 2025-01-08T13:56:39.270Z    INFO    countsincelasts 0, samples required:

publisher app:

publisher-app-1  | 2025-01-08T13:56:38.363Z     INFO    pion-ice/candidate_base.go:335  dst adddrr12.12.12.12:52847
publisher-app-1  | ice INFO: 2025/01/08 13:56:38 Failed to send packet: calling Write() after CloseWrite()
publisher-app-1  | DEBU[0434] received 12 bytes (msg type: 60785)           chSeq=972 connId=3 edgeSeq=886 type=EdgeStateClosedType
publisher-app-1  | DEBU[0434] received ConnState_CLOSED message, closing connection  connId=3 marker=P8-QGUPT
publisher-app-1  | DEBU[0434] close: begin                                  connId=3 marker=P8-QGUPT
publisher-app-1  | DEBU[0434] close: end                                    connId=3 marker=P8-QGUPT
publisher-app-1  | turnc DEBUG: 13:56:38.363502 client.go:181: Failed to read: EOF. Exiting loop

First publisher receives conn closed, then livekit server cleans up.

46

It does look like it could be ziti issue:

this is what i have in my openziti edge router logs:

ziti-edge-router-1  | [7471.082]   ERROR ziti/router/xgress_common.(*XgressConn).WritePayload: {error=[crypto failed]} crypto failed on msg of size=1237, headers=map[]
ziti-edge-router-1  | [7471.082] WARNING ziti/router/xgress.(*Xgress).tx.func3 [{c/bkeKilRaP|@/3EDr}<Terminator>]: {circuitId=[bkeKilRaP] seq=[83186] origin=[Initiator]} write failed (crypto failed), closing xgress

When debuging WritePayload i found that error occours here(ziti/router/xgress_common/connection.go at 01d81228d0b93b42bc8710a1c4830c60e9eaee98 · openziti/ziti · GitHub):

	if len(p) > 0 {
		buf := p
		if self.receiver != nil {
			buf, _, err = self.receiver.Pull(p)
			if err != nil {
				log.WithError(err).Errorf("crypto failed on msg of size=%v, headers=%+v", len(p), headers)
				return 0, err

and within self.receiver.Pull(secretstream/stream.go at 8cdcdee8cf5a32d9c90d6b8f8045753fd5e69dea · openziti/secretstream · GitHub):

if subtle.ConstantTimeCompare(mac, stored_mac) == 0 {
		return nil, 0, cryptoFailure
	}
47

Hi @CarlosHleb

I'm working on getting your example up and running so I can try to duplicate the issue. I'll let you know what I find.

Paul

2 Likes
48

Hello,

Haven't heard from you. Any idea why crypto fails?

Thanks!

49

Hi @CarlosHleb

The good news is that I was able to get your example environment up and running and it does show the crypto error. Bad news is that I haven't tracked it down yet. However, being able to reproduce is a good start and I'll be spending some time this week on debugging.

Cheers,
Paul

2 Likes
50

It seems like concurrent, high-volume writes can cause the E2E encryption stream to get out of sync. I wrote the issue up here: E2E encryption can encounter ordering issues with high-volume concurrent writes · Issue #659 · openziti/sdk-golang · GitHub

Adding a mutex to the write fixed the issue in your example setup. I ran it for several minutes and the circuits stayed stable.

I'll see about getting the fix merged up.

Paul

2 Likes
51

I see there is a release: Release v0.23.45 · openziti/sdk-golang · GitHub

I did 15 minute tests on both ubuntu and windows, no issues found thus far. I updated the code on ziti-livekit-example(no issues there as well).

Thanks for the fix!

2 Likes