feat(proxyd): log sendRawTransaction forwarding with tx_hash and duration (#569)

* feat(proxyd): log sendRawTransaction forwarding with tx_hash and duration

When enable_tx_hash_logging is enabled, proxyd now emits a
"sendRawTransaction forwarded" log after the backend responds. This
correlates req_id with tx_hash and includes backend name, backend group,
and forwarding duration in milliseconds.

This complements the existing "processing sendRawTransaction" log (which
fires at request time) by adding a response-time log that measures
proxyd's internal processing time — useful for flashblocks latency
analysis with op-benchmark.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

* test(proxyd): verify forwarding log fields match request log

Parse the JSON log lines to assert that the "sendRawTransaction
forwarded" log has the correct tx_hash value and that its req_id matches
the corresponding "processing sendRawTransaction" log from the same
request.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

* fix(proxyd): only log sendRawTransaction forwarded on success

Move the forwarding log after the error handling block so it only emits
when Forward() succeeds. Previously it fired before the err check,
producing misleading latency data on failed forwards.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 4.6 <noreply@anthropic.com>

Author: bitwiseguy

proxyd/integration_tests/tx_hash_logging_test.go

@@ -2,16 +2,38 @@ package integration_tests
 
 import (
 	"bytes"
+	"encoding/json"
 	"log/slog"
 	"net/http"
 	"os"
+	"strings"
 	"testing"
 
 	"github.com/ethereum-optimism/infra/proxyd"
 	"github.com/ethereum/go-ethereum/log"
 	"github.com/stretchr/testify/require"
 )
 
+// findJSONLogLine searches JSON log output for a line with the given message
+// and returns the parsed fields, or nil if not found.
+func findJSONLogLine(t *testing.T, logOutput string, msg string) map[string]any {
+	t.Helper()
+	for _, line := range strings.Split(logOutput, "\n") {
+		line = strings.TrimSpace(line)
+		if line == "" {
+			continue
+		}
+		var entry map[string]any
+		if err := json.Unmarshal([]byte(line), &entry); err != nil {
+			continue
+		}
+		if entry["msg"] == msg {
+			return entry
+		}
+	}
+	return nil
+}
+
 func TestTxHashLogging(t *testing.T) {
 	// Capture log output
 	var logBuf bytes.Buffer
@@ -49,6 +71,17 @@ func TestTxHashLogging(t *testing.T) {
 		require.Contains(t, logOutput, "req_id")
 		require.Contains(t, logOutput, "chain_id")
 		require.Contains(t, logOutput, "nonce")
+
+		// Verify forwarding log has correct tx_hash and matching req_id
+		recvLog := findJSONLogLine(t, logOutput, "processing sendRawTransaction")
+		require.NotNil(t, recvLog, "expected processing sendRawTransaction log line")
+
+		fwdLog := findJSONLogLine(t, logOutput, "sendRawTransaction forwarded")
+		require.NotNil(t, fwdLog, "expected sendRawTransaction forwarded log line")
+		require.Equal(t, "0x0cdd497ce38727606708946cd07b83b101b92a29dea7f090f1f09ae849efd1a3", fwdLog["tx_hash"])
+		require.Equal(t, recvLog["req_id"], fwdLog["req_id"], "req_id should match between processing and forwarded logs")
+		require.NotEmpty(t, fwdLog["backend"], "backend should be present")
+		require.NotNil(t, fwdLog["duration_ms"], "duration_ms should be present")
 	})
 
 	t.Run("batch sendRawTransaction should log tx hash", func(t *testing.T) {
@@ -121,6 +154,7 @@ func TestTxHashLoggingDisabled(t *testing.T) {
 		// Verify log does NOT contain transaction hash logging
 		logOutput := logBuf.String()
 		require.NotContains(t, logOutput, "processing sendRawTransaction")
+		require.NotContains(t, logOutput, "sendRawTransaction forwarded")
 		require.NotContains(t, logOutput, "0x0cdd497ce38727606708946cd07b83b101b92a29dea7f090f1f09ae849efd1a3")
 	})
 }

proxyd/server.go

@@ -568,6 +568,7 @@ func (s *Server) handleBatchRPC(ctx context.Context, reqs []json.RawMessage, isL
 	responses := make([]*RPCRes, len(reqs))
 	batches := make(map[batchGroup][]batchElem)
 	ids := make(map[string]int, len(reqs))
+	txHashes := make(map[int]common.Hash) // tracks tx hashes by request index for forwarding logs
 
 	for i := range reqs {
 		parsedReq, err := ParseRPCReq(reqs[i])
@@ -653,6 +654,7 @@ func (s *Server) handleBatchRPC(ctx context.Context, reqs []json.RawMessage, isL
 				responses[i] = NewRPCErrorRes(parsedReq.ID, err)
 				continue
 			}
+			txHashes[i] = tx.Hash()
 			if err := s.rateLimitSender(ctx, tx, bypassLimit); err != nil {
 				RecordRPCError(ctx, BackendProxyd, parsedReq.Method, err)
 				responses[i] = NewRPCErrorRes(parsedReq.ID, err)
@@ -713,8 +715,11 @@ func (s *Server) handleBatchRPC(ctx context.Context, reqs []json.RawMessage, isL
 			start := i * s.maxUpstreamBatchSize
 			end := int(math.Min(float64(start+s.maxUpstreamBatchSize), float64(len(cacheMisses))))
 			elems := cacheMisses[start:end]
+			forwardStart := time.Now()
 			res, sb, err := s.BackendGroups[group.backendGroup].Forward(ctx, createBatchRequest(elems), isBatch)
+			forwardDuration := time.Since(forwardStart)
 			servedBy[sb] = true
+
 			if err != nil {
 				if errors.Is(err, ErrConsensusGetReceiptsCantBeBatched) ||
 					errors.Is(err, ErrConsensusGetReceiptsInvalidTarget) {
@@ -733,6 +738,21 @@ func (s *Server) handleBatchRPC(ctx context.Context, reqs []json.RawMessage, isL
 				}
 			}
 
+			// Log forwarding for sendRawTransaction requests (success path only)
+			if err == nil && s.enableTxHashLogging {
+				for _, elem := range elems {
+					if txHash, ok := txHashes[elem.Index]; ok {
+						log.Info("sendRawTransaction forwarded",
+							"tx_hash", txHash,
+							"req_id", GetReqID(ctx),
+							"backend", sb,
+							"backend_group", group.backendGroup,
+							"duration_ms", forwardDuration.Milliseconds(),
+						)
+					}
+				}
+			}
+
 			for i := range elems {
 				responses[elems[i].Index] = res[i]