Merge pull request #235 from kerberos-io/fix/debugging-lost-keyframes

fix/debugging-lost-keyframes

machinery/src/capture/gortsplib.go

@@ -85,12 +85,8 @@ type Golibrtsp struct {
 
 	Streams []packets.Stream
 
-	// FPS calculation fields
-	lastFrameTime    time.Time
-	frameTimeBuffer  []time.Duration
-	frameBufferSize  int
-	frameBufferIndex int
-	fpsMutex         sync.Mutex
+	// Per-stream FPS calculation (keyed by stream index)
+	fpsTrackers map[int8]*fpsTracker
 
 	// I-frame interval tracking fields
 	packetsSinceLastKeyframe int
@@ -101,6 +97,78 @@ type Golibrtsp struct {
 	keyframeMutex            sync.Mutex
 }
 
+// fpsTracker holds per-stream state for PTS-based FPS calculation.
+// Each video stream (H264 / H265) gets its own tracker so PTS
+// samples from different codecs never interleave.
+type fpsTracker struct {
+	mu              sync.Mutex
+	lastPTS         time.Duration
+	hasPTS          bool
+	frameTimeBuffer []time.Duration
+	bufferSize      int
+	bufferIndex     int
+	cachedFPS       float64 // latest computed FPS
+}
+
+func newFPSTracker(bufferSize int) *fpsTracker {
+	return &fpsTracker{
+		frameTimeBuffer: make([]time.Duration, bufferSize),
+		bufferSize:      bufferSize,
+	}
+}
+
+// update records a new PTS sample and returns the latest FPS estimate.
+// It must be called once per complete decoded frame (after Decode()
+// succeeds), not on every RTP packet fragment.
+func (ft *fpsTracker) update(pts time.Duration) float64 {
+	ft.mu.Lock()
+	defer ft.mu.Unlock()
+
+	if !ft.hasPTS {
+		ft.lastPTS = pts
+		ft.hasPTS = true
+		return 0
+	}
+
+	interval := pts - ft.lastPTS
+	ft.lastPTS = pts
+
+	// Skip invalid intervals (zero, negative, or very large which
+	// indicate a PTS discontinuity or wrap).
+	if interval <= 0 || interval > 5*time.Second {
+		return ft.cachedFPS
+	}
+
+	ft.frameTimeBuffer[ft.bufferIndex] = interval
+	ft.bufferIndex = (ft.bufferIndex + 1) % ft.bufferSize
+
+	var totalInterval time.Duration
+	validSamples := 0
+	for _, iv := range ft.frameTimeBuffer {
+		if iv > 0 {
+			totalInterval += iv
+			validSamples++
+		}
+	}
+	if validSamples == 0 {
+		return ft.cachedFPS
+	}
+	avgInterval := totalInterval / time.Duration(validSamples)
+	if avgInterval == 0 {
+		return ft.cachedFPS
+	}
+
+	ft.cachedFPS = float64(time.Second) / float64(avgInterval)
+	return ft.cachedFPS
+}
+
+// fps returns the most recent FPS estimate without recording a new sample.
+func (ft *fpsTracker) fps() float64 {
+	ft.mu.Lock()
+	defer ft.mu.Unlock()
+	return ft.cachedFPS
+}
+
 // Init function
 var H264FrameDecoder *Decoder
 var H265FrameDecoder *Decoder
@@ -548,18 +616,17 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 
 			if len(rtppkt.Payload) > 0 {
 
-				// decode timestamp
-				pts, ok := g.Client.PacketPTS(g.VideoH264Media, rtppkt)
-				pts2, ok := g.Client.PacketPTS2(g.VideoH264Media, rtppkt)
-				if !ok {
-					log.Log.Debug("capture.golibrtsp.Start(): " + "unable to get PTS")
+				// decode timestamps — validate each call separately
+				pts, okPTS := g.Client.PacketPTS(g.VideoH264Media, rtppkt)
+				pts2, okPTS2 := g.Client.PacketPTS2(g.VideoH264Media, rtppkt)
+				if !okPTS2 {
+					log.Log.Debug("capture.golibrtsp.Start(): unable to get PTS2 from PacketPTS2")
 					return
 				}
 
-				// Extract access units from RTP packets
-				// We need to do this, because the decoder expects a full
-				// access unit. Once we have a full access unit, we can
-				// decode it, and know if it's a keyframe or not.
+				// Extract access units from RTP packets.
+				// We need a complete access unit to determine whether
+				// this is a keyframe.
 				au, errDecode := g.VideoH264Decoder.Decode(rtppkt)
 				if errDecode != nil {
 					if errDecode != rtph264.ErrNonStartingPacketAndNoPrevious && errDecode != rtph264.ErrMorePacketsNeeded {
@@ -568,6 +635,18 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 					return
 				}
 
+				// Frame is complete — update per-stream FPS from PTS.
+				if okPTS {
+					ft := g.fpsTrackers[g.VideoH264Index]
+					if ft == nil {
+						ft = newFPSTracker(30)
+						g.fpsTrackers[g.VideoH264Index] = ft
+					}
+					if ptsFPS := ft.update(pts); ptsFPS > 0 && ptsFPS <= 120 {
+						g.Streams[g.VideoH264Index].FPS = ptsFPS
+					}
+				}
+
 				// We'll need to read out a few things.
 				// prepend an AUD. This is required by some players
 				filteredAU = [][]byte{
@@ -578,8 +657,10 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 				nonIDRPresent := false
 				idrPresent := false
 
+				var naluTypes []string
 				for _, nalu := range au {
 					typ := h264.NALUType(nalu[0] & 0x1F)
+					naluTypes = append(naluTypes, fmt.Sprintf("%s(%d,sz=%d)", typ.String(), int(typ), len(nalu)))
 					switch typ {
 					case h264.NALUTypeAccessUnitDelimiter:
 						continue
@@ -626,6 +707,11 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 					return
 				}
 
+				if idrPresent {
+					log.Log.Debug(fmt.Sprintf("capture.golibrtsp.Start(%s): IDR frame NALUs: [%s]",
+						streamType, fmt.Sprintf("%v", naluTypes)))
+				}
+
 				// Convert to packet.
 				enc, err := h264.AnnexBMarshal(filteredAU)
 				if err != nil {
@@ -651,7 +737,11 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 				keyframeInterval := g.trackKeyframeInterval(idrPresent)
 				if idrPresent && keyframeInterval > 0 {
 					avgInterval := g.getAverageKeyframeInterval()
-					gopDuration := float64(keyframeInterval) / g.Streams[g.VideoH265Index].FPS
+					fps := g.Streams[g.VideoH264Index].FPS
+					if fps <= 0 {
+						fps = 25.0 // Default fallback FPS
+					}
+					gopDuration := float64(keyframeInterval) / fps
 					gopSize := int(avgInterval) // Store GOP size in a separate variable
 					g.Streams[g.VideoH264Index].GopSize = gopSize
 					log.Log.Debug(fmt.Sprintf("capture.golibrtsp.Start(%s): Keyframe interval=%d packets, Avg=%.1f, GOP=%.1fs, GOPSize=%d",
@@ -716,18 +806,17 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 
 			if len(rtppkt.Payload) > 0 {
 
-				// decode timestamp
-				pts, ok := g.Client.PacketPTS(g.VideoH265Media, rtppkt)
-				pts2, ok := g.Client.PacketPTS2(g.VideoH265Media, rtppkt)
-				if !ok {
-					log.Log.Debug("capture.golibrtsp.Start(): " + "unable to get PTS")
+				// decode timestamps — validate each call separately
+				pts, okPTS := g.Client.PacketPTS(g.VideoH265Media, rtppkt)
+				pts2, okPTS2 := g.Client.PacketPTS2(g.VideoH265Media, rtppkt)
+				if !okPTS2 {
+					log.Log.Debug("capture.golibrtsp.Start(): unable to get PTS")
 					return
 				}
 
-				// Extract access units from RTP packets
-				// We need to do this, because the decoder expects a full
-				// access unit. Once we have a full access unit, we can
-				// decode it, and know if it's a keyframe or not.
+				// Extract access units from RTP packets.
+				// We need a complete access unit to determine whether
+				// this is a keyframe.
 				au, errDecode := g.VideoH265Decoder.Decode(rtppkt)
 				if errDecode != nil {
 					if errDecode != rtph265.ErrNonStartingPacketAndNoPrevious && errDecode != rtph265.ErrMorePacketsNeeded {
@@ -736,6 +825,18 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 					return
 				}
 
+				// Frame is complete — update per-stream FPS from PTS.
+				if okPTS {
+					ft := g.fpsTrackers[g.VideoH265Index]
+					if ft == nil {
+						ft = newFPSTracker(30)
+						g.fpsTrackers[g.VideoH265Index] = ft
+					}
+					if ptsFPS := ft.update(pts); ptsFPS > 0 && ptsFPS <= 120 {
+						g.Streams[g.VideoH265Index].FPS = ptsFPS
+					}
+				}
+
 				filteredAU = [][]byte{
 					{byte(h265.NALUType_AUD_NUT) << 1, 1, 0x50},
 				}
@@ -796,7 +897,11 @@ func (g *Golibrtsp) Start(ctx context.Context, streamType string, queue *packets
 				keyframeInterval := g.trackKeyframeInterval(isRandomAccess)
 				if isRandomAccess && keyframeInterval > 0 {
 					avgInterval := g.getAverageKeyframeInterval()
-					gopDuration := float64(keyframeInterval) / g.Streams[g.VideoH265Index].FPS
+					fps := g.Streams[g.VideoH265Index].FPS
+					if fps <= 0 {
+						fps = 25.0 // Default fallback FPS
+					}
+					gopDuration := float64(keyframeInterval) / fps
 					gopSize := int(avgInterval) // Store GOP size in a separate variable
 					g.Streams[g.VideoH265Index].GopSize = gopSize
 					log.Log.Debug(fmt.Sprintf("capture.golibrtsp.Start(%s): Keyframe interval=%d packets, Avg=%.1f, GOP=%.1fs, GOPSize=%d",
@@ -1179,10 +1284,11 @@ func WriteMPEG4Audio(forma *format.MPEG4Audio, aus [][]byte) ([]byte, error) {
 
 // Initialize FPS calculation buffers
 func (g *Golibrtsp) initFPSCalculation() {
-	g.frameBufferSize = 30 // Store last 30 frame intervals
-	g.frameTimeBuffer = make([]time.Duration, g.frameBufferSize)
-	g.frameBufferIndex = 0
-	g.lastFrameTime = time.Time{}
+	// Ensure the per-stream FPS trackers map exists. Individual trackers
+	// can be created lazily when a given stream index is first used.
+	if g.fpsTrackers == nil {
+		g.fpsTrackers = make(map[int8]*fpsTracker)
+	}
 
 	// Initialize I-frame interval tracking
 	g.keyframeBufferSize = 10 // Store last 10 keyframe intervals
@@ -1192,50 +1298,11 @@ func (g *Golibrtsp) initFPSCalculation() {
 	g.lastKeyframePacketCount = 0
 }
 
-// Calculate FPS from frame timestamps
-func (g *Golibrtsp) calculateFPSFromTimestamps() float64 {
-	g.fpsMutex.Lock()
-	defer g.fpsMutex.Unlock()
-
-	if g.lastFrameTime.IsZero() {
-		g.lastFrameTime = time.Now()
-		return 0
-	}
-
-	now := time.Now()
-	interval := now.Sub(g.lastFrameTime)
-	g.lastFrameTime = now
-
-	// Store the interval
-	g.frameTimeBuffer[g.frameBufferIndex] = interval
-	g.frameBufferIndex = (g.frameBufferIndex + 1) % g.frameBufferSize
-
-	// Calculate average FPS from stored intervals
-	var totalInterval time.Duration
-	validSamples := 0
-
-	for _, interval := range g.frameTimeBuffer {
-		if interval > 0 {
-			totalInterval += interval
-			validSamples++
-		}
-	}
-
-	if validSamples == 0 {
-		return 0
-	}
-
-	avgInterval := totalInterval / time.Duration(validSamples)
-	if avgInterval == 0 {
-		return 0
-	}
-
-	return float64(time.Second) / float64(avgInterval)
-}
-
-// Get enhanced FPS information from SPS with fallback
+// Get enhanced FPS information from SPS with fallback to PTS-based calculation.
+// The PTS-based FPS is computed per completed frame via fpsTracker.update(),
+// so by the time this is called we already have a good estimate.
 func (g *Golibrtsp) getEnhancedFPS(sps *h264.SPS, streamIndex int8) float64 {
-	// First try to get FPS from SPS
+	// First try to get FPS from SPS VUI parameters
 	spsFPS := sps.FPS()
 
 	// Check if SPS FPS is reasonable (between 1 and 120 fps)
@@ -1244,11 +1311,13 @@ func (g *Golibrtsp) getEnhancedFPS(sps *h264.SPS, streamIndex int8) float64 {
 		return spsFPS
 	}
 
-	// Fallback to timestamp-based calculation
-	timestampFPS := g.calculateFPSFromTimestamps()
-	if timestampFPS > 0 && timestampFPS <= 120 {
-		log.Log.Debug(fmt.Sprintf("capture.golibrtsp.getEnhancedFPS(): Timestamp FPS: %.2f", timestampFPS))
-		return timestampFPS
+	// Fallback to PTS-based FPS (already calculated per-frame)
+	if ft := g.fpsTrackers[streamIndex]; ft != nil {
+		ptsFPS := ft.fps()
+		if ptsFPS > 0 && ptsFPS <= 120 {
+			log.Log.Debug(fmt.Sprintf("capture.golibrtsp.getEnhancedFPS(): PTS FPS: %.2f", ptsFPS))
+			return ptsFPS
+		}
 	}
 
 	// Return SPS FPS even if it seems unreasonable, or default

machinery/src/video/mp4.go

@@ -189,6 +189,11 @@ func (mp4 *MP4) flushPendingVideoSample(nextPTS uint64) bool {
 
 func (mp4 *MP4) AddSampleToTrack(trackID uint32, isKeyframe bool, data []byte, pts uint64) error {
 
+	if isKeyframe && trackID == uint32(mp4.VideoTrack) {
+		log.Log.Debug(fmt.Sprintf("mp4.AddSampleToTrack(): KEYFRAME received - track=%d, PTS=%d, size=%d, sampleCount=%d",
+			trackID, pts, len(data), mp4.SampleCount))
+	}
+
 	if isKeyframe {
 
 		// Determine whether to start a new fragment.

machinery/src/webrtc/main.go

@@ -49,6 +49,7 @@ type peerConnectionWrapper struct {
 	conn      *pionWebRTC.PeerConnection
 	cancelCtx context.CancelFunc
 	done      chan struct{}
+	closeOnce sync.Once
 }
 
 var globalConnectionManager = NewConnectionManager()
@@ -339,18 +340,20 @@ func InitializeWebRTCConnection(configuration *models.Configuration, communicati
 
 				switch connectionState {
 				case pionWebRTC.PeerConnectionStateDisconnected, pionWebRTC.PeerConnectionStateClosed:
-					count := globalConnectionManager.DecrementPeerCount()
-					log.Log.Info("webrtc.main.InitializeWebRTCConnection(): Peer disconnected. Active peers: " + string(rune(count)))
+					wrapper.closeOnce.Do(func() {
+						count := globalConnectionManager.DecrementPeerCount()
+						log.Log.Info("webrtc.main.InitializeWebRTCConnection(): Peer disconnected. Active peers: " + string(rune(count)))
 
-					// Clean up resources
-					globalConnectionManager.CloseCandidateChannel(sessionKey)
+						// Clean up resources
+						globalConnectionManager.CloseCandidateChannel(sessionKey)
 
-					if err := peerConnection.Close(); err != nil {
-						log.Log.Error("webrtc.main.InitializeWebRTCConnection(): error closing peer connection: " + err.Error())
-					}
+						if err := peerConnection.Close(); err != nil {
+							log.Log.Error("webrtc.main.InitializeWebRTCConnection(): error closing peer connection: " + err.Error())
+						}
 
-					globalConnectionManager.RemovePeerConnection(handshake.SessionID)
-					close(wrapper.done)
+						globalConnectionManager.RemovePeerConnection(handshake.SessionID)
+						close(wrapper.done)
+					})
 
 				case pionWebRTC.PeerConnectionStateConnected:
 					count := globalConnectionManager.IncrementPeerCount()