From d8b6751486562bc3565cb1a50cc364bae2a68ffd Mon Sep 17 00:00:00 2001
From: Jannik Luhn <jannik.luhn@posteo.de>
Date: Tue, 11 Jun 2024 17:38:09 +0200
Subject: [PATCH] Log message validation and handle durations

---
 rolling-shutter/p2p/messaging.go | 22 +++++++++++++++++++++-
 1 file changed, 21 insertions(+), 1 deletion(-)

diff --git a/rolling-shutter/p2p/messaging.go b/rolling-shutter/p2p/messaging.go
index 54b3c023f..3b5d712fc 100644
--- a/rolling-shutter/p2p/messaging.go
+++ b/rolling-shutter/p2p/messaging.go
@@ -3,6 +3,7 @@ package p2p
 import (
 	"context"
 	"reflect"
+	"time"
 
 	"github.com/hashicorp/go-multierror"
 	pubsub "github.com/libp2p/go-libp2p-pubsub"
@@ -30,6 +31,15 @@ type (
 
 func (r *ValidatorRegistry) GetCombinedValidator(topic string) pubsub.ValidatorEx {
 	validate := func(ctx context.Context, sender peer.ID, message *pubsub.Message) pubsub.ValidationResult {
+		startTime := time.Now()
+		defer func() {
+			elapsedTime := time.Since(startTime)
+			log.Debug().
+				Str("topic", topic).
+				Str("duration", elapsedTime.String()).
+				Msg("validated message")
+		}()
+
 		ignored := false
 		for _, valFunc := range (*r)[topic] {
 			res := valFunc(ctx, sender, message)
@@ -284,11 +294,21 @@ var (
 )
 
 func (m *P2PMessaging) Handle(ctx context.Context, msg p2pmsg.Message) ([]p2pmsg.Message, error) {
+	startTime := time.Now()
+	messageName := proto.MessageName(msg)
+	defer func() {
+		elapsedTime := time.Since(startTime)
+		log.Debug().
+			Str("message-name", string(messageName)).
+			Str("duration", elapsedTime.String()).
+			Msg("handled message")
+	}()
+
 	var (
 		msgsOut   []p2pmsg.Message
 		errResult error
 	)
-	fns, exists := m.handlerRegistry[proto.MessageName(msg)]
+	fns, exists := m.handlerRegistry[messageName]
 	if !exists {
 		return nil, ErrNoMessageHandler
 	}