From 0937850268b5a0e339347a355a4c3b3b4557bb0a Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?rich=CE=9Brd?= <info@richardramos.me>
Date: Tue, 21 May 2024 13:29:29 -0400
Subject: [PATCH] chore: use custom logger for message timestamps and log query
 duration (#5199)

* chore_: use custom logger for message timestamps
* chore_: log store query duration
---
 logutils/custom.go | 15 +++++++++++++++
 wakuv2/waku.go     |  9 +++++++--
 2 files changed, 22 insertions(+), 2 deletions(-)
 create mode 100644 logutils/custom.go

diff --git a/logutils/custom.go b/logutils/custom.go
new file mode 100644
index 000000000..b876c08bc
--- /dev/null
+++ b/logutils/custom.go
@@ -0,0 +1,15 @@
+package logutils
+
+import (
+	"fmt"
+
+	"go.uber.org/zap"
+)
+
+func WakuMessageTimestamp(key string, value *int64) zap.Field {
+	valueStr := "-"
+	if value != nil {
+		valueStr = fmt.Sprintf("%d", *value)
+	}
+	return zap.String(key, valueStr)
+}
diff --git a/wakuv2/waku.go b/wakuv2/waku.go
index 792750003..7667e933b 100644
--- a/wakuv2/waku.go
+++ b/wakuv2/waku.go
@@ -69,6 +69,7 @@ import (
 
 	"github.com/status-im/status-go/connection"
 	"github.com/status-im/status-go/eth-node/types"
+	"github.com/status-im/status-go/logutils"
 	"github.com/status-im/status-go/timesource"
 	"github.com/status-im/status-go/wakuv2/common"
 	"github.com/status-im/status-go/wakuv2/persistence"
@@ -1079,8 +1080,8 @@ func (w *Waku) query(ctx context.Context, peerID peer.ID, pubsubTopic string, to
 
 	w.logger.Debug("store.query",
 		zap.String("requestID", hexutil.Encode(requestID)),
-		zap.Int64p("startTime", query.StartTime),
-		zap.Int64p("endTime", query.EndTime),
+		logutils.WakuMessageTimestamp("startTime", query.StartTime),
+		logutils.WakuMessageTimestamp("endTime", query.EndTime),
 		zap.Strings("contentTopics", query.ContentTopics),
 		zap.String("pubsubTopic", query.PubsubTopic),
 		zap.Stringer("peerID", peerID))
@@ -1092,7 +1093,10 @@ func (w *Waku) Query(ctx context.Context, peerID peer.ID, pubsubTopic string, to
 	requestID := protocol.GenerateRequestID()
 	pubsubTopic = w.getPubsubTopic(pubsubTopic)
 
+	queryStart := time.Now()
 	result, err := w.query(ctx, peerID, pubsubTopic, topics, from, to, requestID, opts)
+	queryDuration := time.Since(queryStart)
+
 	if err != nil {
 		w.logger.Error("error querying storenode",
 			zap.String("requestID", hexutil.Encode(requestID)),
@@ -1106,6 +1110,7 @@ func (w *Waku) Query(ctx context.Context, peerID peer.ID, pubsubTopic string, to
 	}
 
 	envelopesCount = len(result.Messages)
+	w.logger.Debug("store.query response", zap.Duration("queryDuration", queryDuration), zap.Int("numMessages", envelopesCount), zap.Bool("hasCursor", result.IsComplete() && result.Cursor() != nil))
 
 	for _, msg := range result.Messages {
 		// Temporarily setting RateLimitProof to nil so it matches the WakuMessage protobuffer we are sending