vidforward: improve non-active mechanism

This change improves the mechanism that deals with recv requests
from non active macs. We're no only logging every minute so that
we don't clutter the logs. We're also dealing with both non active
and slate recvs with the same mechanism using a switch.

cmd/vidforward/main.go

@@ -106,11 +106,12 @@ func (b *Broadcast) equal(other Broadcast) bool {
 // and a recv handler which is invoked when a camera wishes to get its video
 // forwarded to youtube.
 type broadcastManager struct {
-	broadcasts       map[MAC]*Broadcast
-	slateExitSignals map[MAC]chan struct{} // Used to signal to stop writing slate image.
-	log              logging.Logger
-	dogNotifier      *watchdogNotifier
-	mu               sync.Mutex
+	broadcasts          map[MAC]*Broadcast
+	slateExitSignals    map[MAC]chan struct{} // Used to signal to stop writing slate image.
+	lastLoggedNonActive map[MAC]time.Time     // Used to log non-active MACs every minute.
+	log                 logging.Logger
+	dogNotifier         *watchdogNotifier
+	mu                  sync.Mutex
 }
 
 // newBroadcastManager returns a new broadcastManager with the provided logger.
@@ -196,17 +197,39 @@ func (m *broadcastManager) recv(w http.ResponseWriter, r *http.Request) {
 	q := r.URL.Query()
 	ma := MAC(q.Get("ma"))
 
-	if !m.isActive(ma) {
-		m.errorLogWrite(m.log, w, "forward request mac is not mapped, doing nothing", "mac", ma)
-		time.Sleep(recvErrorDelay)
-		return
-	}
+	// Check that we're not receiving video when we shouldn't be. There's
+	// two conditions when this can happen; when the MAC is not mapped to a
+	// broadcast, or when the broadcast is in slate mode.
+	// It's expected this might happen a little bit under normal operation.
+	// It's difficult to get the camera power timing right, so we might
+	// receive a request before the camera has been registered, or after
+	// we've transitioned into slate mode.
+	// If this happens too much however, it may indicate a problem.
+	var reason string
+	switch {
+	case !m.isActive(ma):
+		reason = "forward request mac is not mapped, doing nothing"
+		fallthrough
+	case m.getStatus(ma) == statusSlate:
+		if reason == "" {
+			reason = "cannot receive video for this mac, status is slate"
+		}
 
-	// We can't receive video if we're in slate mode.
-	if m.getStatus(ma) == statusSlate {
-		m.errorLogWrite(m.log, w, "cannot receive video for this mac, status is slate", "mac", ma)
+		// We don't want to clutter the logs so only log non-active MACs every
+		// minute.
+		const logNonActiveInternal = 1 * time.Minute
+		last, ok := m.lastLoggedNonActive[ma]
+		if !ok || ok && time.Now().Sub(last) > logNonActiveInternal {
+			m.errorLogWrite(m.log, w, reason, "mac", ma)
+			m.lastLoggedNonActive[ma] = time.Now()
+		}
+
+		// Stall the client with a delay to prevent spamming. Probably cause timeout
+		// on client.
 		time.Sleep(recvErrorDelay)
 		return
+
+	default: // Continue (seems like mac is active and we're not in slate.)
 	}
 
 	const videoPin = "V0"