chore: improve debug logs

bridge/events.go

@@ -16,7 +16,6 @@ func (s *Server) runEventLoop(ctx context.Context, failureSink chan<- error) {
 	go func() {
 		l.Info("VPN HA-monitor bridge event loop is starting...",
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 
 		for e := range s.events {
@@ -73,7 +72,6 @@ func (s *Server) runEventLoop(ctx context.Context, failureSink chan<- error) {
 
 		l.Info("VPN HA-monitor bridge event loop is stopped",
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 	}()
 }

bridge/events_bridge.go

@@ -14,7 +14,6 @@ func (s *Server) eventBridgeWentDown(ctx context.Context, e *event.BridgeWentDow
 
 	l.Info("Bridge went down",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 
 	s.mxStatus.Lock()
@@ -43,7 +42,6 @@ func (s *Server) eventBridgeWentUp(ctx context.Context, e *event.BridgeWentUp, _
 
 	l.Info("Bridge went up",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 
 	s.mxStatus.Lock()
@@ -85,7 +83,6 @@ func (s *Server) eventBridgeDeactivated(ctx context.Context, _ *event.BridgeDeac
 
 	l.Info("Bridge deactivated",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 }
 
@@ -94,7 +91,6 @@ func (s *Server) eventBridgeActivated(ctx context.Context, e *event.BridgeActiva
 
 	l.Info("Bridge activated",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 
 	s.executor.ExecuteBridgeActivate(ctx, e)

bridge/events_connectivity.go

@@ -13,7 +13,6 @@ func (s *Server) eventConnectivityLost(ctx context.Context, _ *event.Connectivit
 
 	l.Info("Connectivity lost",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 }
 
@@ -22,6 +21,5 @@ func (s *Server) eventConnectivityRestored(ctx context.Context, _ *event.Connect
 
 	l.Info("Connectivity restored",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 }

bridge/events_partner.go

@@ -58,7 +58,6 @@ func (s *Server) eventPartnerWentDown(ctx context.Context, e *event.PartnerWentD
 
 	l.Info("Partner went down",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 
 	s.mxStatus.Lock()
@@ -88,7 +87,6 @@ func (s *Server) eventPartnerWentUp(ctx context.Context, e *event.PartnerWentUp,
 
 	l.Info("Partner went up",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 
 	s.mxStatus.Lock()
@@ -107,7 +105,6 @@ func (s *Server) eventPartnerDeactivated(ctx context.Context, _ *event.PartnerDe
 
 	l.Info("Partner deactivated",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 }
 
@@ -116,7 +113,6 @@ func (s *Server) eventPartnerActivated(ctx context.Context, _ *event.PartnerActi
 
 	logFields := []zapcore.Field{
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	}
 	if s.partnerStatus != nil {
 		logFields = append(logFields, zap.String("partner_name", s.partnerStatus.Name))

bridge/events_tunnel_interface.go

@@ -14,7 +14,6 @@ func (s *Server) eventTunnelInterfaceWentDown(ctx context.Context, e *event.Tunn
 
 	l.Info("Tunnel interface went down",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 		zap.String("tunnel_interface", e.EvtTunnelInterface()),
 	)
 
@@ -65,7 +64,6 @@ func (s *Server) eventTunnelInterfaceWentUp(ctx context.Context, e *event.Tunnel
 
 	l.Info("Tunnel interface went up",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 		zap.String("tunnel_interface", e.EvtTunnelInterface()),
 	)
 
@@ -143,7 +141,6 @@ func (s *Server) eventTunnelInterfaceDeactivated(ctx context.Context, e *event.T
 
 	l.Info("Tunnel interface deactivated",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 		zap.String("tunnel_interface", e.EvtTunnelInterface()),
 	)
 
@@ -155,7 +152,6 @@ func (s *Server) eventTunnelInterfaceActivated(ctx context.Context, e *event.Tun
 
 	l.Info("Tunnel interface activated",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 		zap.String("tunnel_interface", e.EvtTunnelInterface()),
 	)
 

bridge/handlers.go

@@ -28,7 +28,6 @@ func (s *Server) handleStatus(w http.ResponseWriter, r *http.Request) {
 		l.Warn("Failed to read request body",
 			zap.Error(err),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 	}
 
@@ -41,7 +40,6 @@ func (s *Server) handleStatus(w http.ResponseWriter, r *http.Request) {
 		l.Warn("Failed to encode and send response body",
 			zap.Error(err),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 	}
 }
@@ -52,6 +50,16 @@ func (s *Server) handleProbe(
 	from *net.UDPAddr,
 	probe *types.Probe,
 ) {
+	l := logutils.LoggerFromContext(ctx)
+
+	l.Debug("Received probe",
+		zap.String("bridge_name", s.cfg.Name),
+		zap.String("src_uuid", probe.SrcUUID.String()),
+		zap.String("tunnel_interface", tp.InterfaceName()),
+		zap.Time("dst_timestamp", probe.DstTimestamp),
+		zap.Uint64("sequence", probe.Sequence),
+	)
+
 	switch {
 	// reply to the other side's probes
 	case probe.DstTimestamp.IsZero():
@@ -72,7 +80,6 @@ func (s *Server) handleTick(ctx context.Context, ts time.Time, failureSink chan<
 
 	l.Debug("Handling timer tick",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 		zap.Time("tick", ts),
 	)
 

bridge/observer.go

@@ -15,7 +15,6 @@ func (s *Server) ObserveMetrics(ctx context.Context, observer otelapi.Observer)
 
 	l.Debug("Observing metrics",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 	)
 
 	s.mxStatus.Lock()

bridge/polling.go

@@ -39,7 +39,6 @@ func (s *Server) pollPartnerBridge(ctx context.Context, _ chan<- error) {
 		l.Debug("Failed to query partner bridge status",
 			zap.Error(err),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 		s.events <- &event.PartnerPollFailure{ // emit event
 			Sequence:  sequence,
@@ -54,7 +53,6 @@ func (s *Server) pollPartnerBridge(ctx context.Context, _ chan<- error) {
 		l.Warn("Failed to read partner bridge status",
 			zap.Error(err),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 		s.events <- &event.PartnerPollFailure{ // emit event
 			Sequence:  sequence,
@@ -68,7 +66,6 @@ func (s *Server) pollPartnerBridge(ctx context.Context, _ chan<- error) {
 		l.Warn("Failed to parse partner bridge status",
 			zap.Error(err),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 		s.events <- &event.PartnerPollFailure{ // emit event
 			Sequence:  sequence,

bridge/probing.go

@@ -17,6 +17,10 @@ func (s *Server) sendProbes(ctx context.Context, _ chan<- error) {
 	l := logutils.LoggerFromContext(ctx)
 
 	for ifsName, peer := range s.peers {
+		l.Debug("Sending probe to a peer...",
+			zap.String("tunnel_interface", peer.InterfaceName()),
+		)
+
 		probe := &types.Probe{
 			Sequence:     peer.NextSequence(),
 			SrcUUID:      s.uuid,
@@ -30,8 +34,8 @@ func (s *Server) sendProbes(ctx context.Context, _ chan<- error) {
 				l.Warn("Failed to send a probe",
 					zap.Error(err),
 					zap.String("bridge_name", s.cfg.Name),
-					zap.String("bridge_uuid", s.uuid.String()),
 					zap.String("tunnel_interface", peer.InterfaceName()),
+					zap.Uint64("sequence", probe.Sequence),
 				)
 				s.events <- &event.TunnelProbeSendFailure{ // emit event
 					TunnelInterface: ifsName,
@@ -41,6 +45,11 @@ func (s *Server) sendProbes(ctx context.Context, _ chan<- error) {
 				return
 			}
 
+			l.Debug("Sent a probe",
+				zap.String("bridge_name", s.cfg.Name),
+				zap.String("tunnel_interface", peer.InterfaceName()),
+				zap.Uint64("sequence", probe.Sequence),
+			)
 			s.events <- &event.TunnelProbeSendSuccess{ // emit event
 				TunnelInterface: ifsName,
 				ProbeSequence:   probe.Sequence,
@@ -50,10 +59,17 @@ func (s *Server) sendProbes(ctx context.Context, _ chan<- error) {
 	}
 }
 
-func (s *Server) detectMissedProbes(_ context.Context, _ chan<- error) {
+func (s *Server) detectMissedProbes(ctx context.Context, _ chan<- error) {
+	l := logutils.LoggerFromContext(ctx)
+
 	for ifsName, peer := range s.peers {
 		for missed := peer.Acknowledgement() + 1; missed < peer.Sequence(); missed++ {
-			s.events <- &event.TunnelProbeReturnFailure{
+			l.Debug("Missed a probe (gap in acknowledgement)",
+				zap.String("bridge_name", s.cfg.Name),
+				zap.String("tunnel_interface", peer.InterfaceName()),
+				zap.Uint64("sequence", missed),
+			)
+			s.events <- &event.TunnelProbeReturnFailure{ // emit event
 				TunnelInterface: ifsName,
 				Timestamp:       time.Now(),
 				ProbeSequence:   missed,
@@ -72,18 +88,24 @@ func (s *Server) respondToProbe(
 	l := logutils.LoggerFromContext(ctx)
 
 	probe.DstLocation = s.cfg.ProbeLocation
+	probe.DstUUID = s.cfg.UUID
 	probe.DstTimestamp = time.Now()
 
 	tp.SendProbe(probe, from, func(err error) {
-		if err != nil {
+		if err == nil {
+			l.Debug("Responded to probe",
+				zap.String("bridge_name", s.cfg.Name),
+				zap.String("dst_uuid", probe.DstUUID.String()),
+				zap.String("tunnel_interface", tp.InterfaceName()),
+				zap.Time("dst_timestamp", probe.DstTimestamp),
+				zap.Uint64("sequence", probe.Sequence),
+			)
+		} else {
 			l.Warn("Failed to respond to incoming probe",
 				zap.Error(err),
 				zap.String("bridge_name", s.cfg.Name),
-				zap.String("bridge_uuid", s.uuid.String()),
-				zap.String("probe_src_addr", from.String()),
-				zap.String("probe_src_location", probe.SrcLocation.String()),
-				zap.String("probe_src_uuid", probe.SrcUUID.String()),
 				zap.String("tunnel_interface", tp.InterfaceName()),
+				zap.Uint64("sequence", probe.Sequence),
 			)
 		}
 	})
@@ -99,12 +121,17 @@ func (s *Server) processReturnedProbe(
 
 	l := logutils.LoggerFromContext(ctx)
 
+	l.Debug("Processing returned probe...",
+		zap.String("bridge_name", s.cfg.Name),
+		zap.String("tunnel_interface", tp.InterfaceName()),
+		zap.Uint64("sequence", probe.Sequence),
+	)
+
 	peer := s.peers[tp.InterfaceName()]
 	// check for errors
 	if probe.DstUUID != peer.UUID() {
 		l.Warn("Invalid return probe",
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 			zap.String("tunnel_interface", tp.InterfaceName()),
 
 			zap.Error(fmt.Errorf("%w: expected %s, got %s",
@@ -115,7 +142,12 @@ func (s *Server) processReturnedProbe(
 	}
 	// detect missed probes
 	for missed := peer.Acknowledgement() + 1; missed < probe.Sequence; missed++ {
-		s.events <- &event.TunnelProbeReturnFailure{
+		l.Debug("Missed a probe (later probe came in)",
+			zap.String("bridge_name", s.cfg.Name),
+			zap.String("tunnel_interface", peer.InterfaceName()),
+			zap.Uint64("sequence", missed),
+		)
+		s.events <- &event.TunnelProbeReturnFailure{ // emit event
 			TunnelInterface: tp.InterfaceName(),
 			ProbeSequence:   missed,
 			Timestamp:       ts,
@@ -142,7 +174,6 @@ func (s *Server) processMismatchedReturnedProbes(
 
 	l.Warn("Invalid probe",
 		zap.String("bridge_name", s.cfg.Name),
-		zap.String("bridge_uuid", s.uuid.String()),
 		zap.String("tunnel_interface", tp.InterfaceName()),
 
 		zap.Error(fmt.Errorf("%w: expected %s, got %s",

bridge/server.go

@@ -163,14 +163,12 @@ func (s *Server) Run(ctx context.Context, failureSink chan<- error) {
 		l.Info("VPN HA-monitor bridge server is going up...",
 			zap.String("bridge_listen_address", s.server.Addr),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 		if err := s.server.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) {
 			failureSink <- err
 		}
 		l.Info("VPN HA-monitor bridge server is down",
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 	}()
 
@@ -200,7 +198,6 @@ func (s *Server) Stop(ctx context.Context) {
 		l.Error("VPN HA-monitor bridge server shutdown failed",
 			zap.Error(err),
 			zap.String("bridge_name", s.cfg.Name),
-			zap.String("bridge_uuid", s.uuid.String()),
 		)
 	}
 }

executor/execute.go

@@ -6,6 +6,7 @@ import (
 	"os"
 	"os/exec"
 	"strings"
+	"time"
 
 	"github.com/flashbots/vpnham/logutils"
 	"github.com/flashbots/vpnham/types"
@@ -46,7 +47,9 @@ func (ex *Executor) execute(ctx context.Context, job job) {
 		ctx, cancel := context.WithTimeout(ctx, ex.timeout)
 		defer cancel()
 
+		start := time.Now()
 		cmd := exec.CommandContext(ctx, _cmd[0], _cmd[1:]...)
+		duration := time.Since(start)
 
 		stdout := &strings.Builder{}
 		stderr := &strings.Builder{}
@@ -61,12 +64,15 @@ func (ex *Executor) execute(ctx context.Context, job job) {
 		}
 
 		l.Info("Executed command",
-			zap.Error(err),
+			zap.String("script", job.name),
 			zap.Int("step", step),
 			zap.String("command", strCmd),
-			zap.String("script", job.name),
+			zap.Duration("duration", duration),
+
 			zap.String("stderr", strings.TrimSpace(stderr.String())),
 			zap.String("stdout", strings.TrimSpace(stdout.String())),
+
+			zap.Error(err),
 		)
 	}
 }