Merge pull request #5980 from onflow/petera/less-logging-script-exec-…

…v0.33

engine/access/rpc/backend/backend_scripts.go

@@ -134,7 +134,7 @@ func (b *backendScripts) executeScript(
 		// issues for some scripts.
 		execResult, execDuration, execErr := b.executeScriptOnAvailableExecutionNodes(ctx, scriptRequest)
 
-		resultComparer := newScriptResultComparison(b.log, b.metrics, scriptRequest)
+		resultComparer := newScriptResultComparison(b.log, b.metrics, b.shouldLogScript, scriptRequest)
 		_ = resultComparer.compare(
 			newScriptResult(execResult, execDuration, execErr),
 			newScriptResult(localResult, localDuration, localErr),
@@ -152,7 +152,7 @@ func (b *backendScripts) executeScript(
 		}
 		localResult, localDuration, localErr := b.executeScriptLocally(ctx, scriptRequest)
 
-		resultComparer := newScriptResultComparison(b.log, b.metrics, scriptRequest)
+		resultComparer := newScriptResultComparison(b.log, b.metrics, b.shouldLogScript, scriptRequest)
 		_ = resultComparer.compare(
 			newScriptResult(execResult, execDuration, execErr),
 			newScriptResult(localResult, localDuration, localErr),
@@ -191,9 +191,11 @@ func (b *backendScripts) executeScriptLocally(
 
 		switch status.Code(convertedErr) {
 		case codes.InvalidArgument, codes.Canceled, codes.DeadlineExceeded:
-			lg.Debug().Err(err).
-				Str("script", string(r.script)).
-				Msg("script failed to execute locally")
+			logEvent := lg.Debug().Err(err)
+			if b.shouldLogScript(execEndTime, r.insecureScriptHash) {
+				logEvent.Str("script", string(r.script))
+			}
+			logEvent.Msg("script failed to execute locally")
 
 		default:
 			lg.Error().Err(err).Msg("script execution failed")
@@ -203,7 +205,7 @@ func (b *backendScripts) executeScriptLocally(
 		return nil, execDuration, convertedErr
 	}
 
-	if b.log.GetLevel() == zerolog.DebugLevel && b.shouldLogScript(execEndTime, r.insecureScriptHash) {
+	if b.shouldLogScript(execEndTime, r.insecureScriptHash) {
 		lg.Debug().
 			Str("script", string(r.script)).
 			Msg("Successfully executed script")
@@ -233,6 +235,7 @@ func (b *backendScripts) executeScriptOnAvailableExecutionNodes(
 		Logger()
 
 	var result []byte
+	var executionTime time.Time
 	var execDuration time.Duration
 	errToReturn := b.nodeCommunicator.CallAvailableNode(
 		executors,
@@ -241,22 +244,20 @@ func (b *backendScripts) executeScriptOnAvailableExecutionNodes(
 
 			result, err = b.tryExecuteScriptOnExecutionNode(ctx, node.Address, r)
 
-			executionTime := time.Now()
+			executionTime = time.Now()
 			execDuration = executionTime.Sub(execStartTime)
 
 			if err != nil {
 				return err
 			}
 
-			if b.log.GetLevel() == zerolog.DebugLevel {
-				if b.shouldLogScript(executionTime, r.insecureScriptHash) {
-					lg.Debug().
-						Str("script_executor_addr", node.Address).
-						Str("script", string(r.script)).
-						Dur("execution_dur_ms", execDuration).
-						Msg("Successfully executed script")
-					b.loggedScripts.Add(r.insecureScriptHash, executionTime)
-				}
+			if b.shouldLogScript(executionTime, r.insecureScriptHash) {
+				lg.Debug().
+					Str("script_executor_addr", node.Address).
+					Str("script", string(r.script)).
+					Dur("execution_dur_ms", execDuration).
+					Msg("Successfully executed script")
+				b.loggedScripts.Add(r.insecureScriptHash, executionTime)
 			}
 
 			// log execution time
@@ -266,10 +267,11 @@ func (b *backendScripts) executeScriptOnAvailableExecutionNodes(
 		},
 		func(node *flow.Identity, err error) bool {
 			if status.Code(err) == codes.InvalidArgument {
-				lg.Debug().Err(err).
-					Str("script_executor_addr", node.Address).
-					Str("script", string(r.script)).
-					Msg("script failed to execute on the execution node")
+				logEvent := lg.Debug().Err(err).Str("script_executor_addr", node.Address)
+				if b.shouldLogScript(executionTime, r.insecureScriptHash) {
+					logEvent.Str("script", string(r.script))
+				}
+				logEvent.Msg("script failed to execute on the execution node")
 				return true
 			}
 			return false
@@ -318,6 +320,9 @@ func isInvalidArgumentError(scriptExecutionErr error) bool {
 
 // shouldLogScript checks if the script hash is unique in the time window
 func (b *backendScripts) shouldLogScript(execTime time.Time, scriptHash [md5.Size]byte) bool {
+	if b.log.GetLevel() > zerolog.DebugLevel {
+		return false
+	}
 	timestamp, seen := b.loggedScripts.Get(scriptHash)
 	if seen {
 		return execTime.Sub(timestamp) >= uniqueScriptLoggingTimeWindow

engine/access/rpc/backend/script_comparer.go

@@ -2,6 +2,8 @@ package backend
 
 import (
 	"bytes"
+	"crypto/md5" //nolint:gosec
+	"encoding/base64"
 	"strings"
 	"time"
 
@@ -14,6 +16,7 @@ import (
 
 const (
 	executeErrorPrefix = "failed to execute script at block"
+	logDiffAsError     = false
 )
 
 type scriptResult struct {
@@ -31,20 +34,23 @@ func newScriptResult(result []byte, duration time.Duration, err error) *scriptRe
 }
 
 type scriptResultComparison struct {
-	log     zerolog.Logger
-	metrics module.BackendScriptsMetrics
-	request *scriptExecutionRequest
+	log             zerolog.Logger
+	metrics         module.BackendScriptsMetrics
+	request         *scriptExecutionRequest
+	shouldLogScript func(time.Time, [md5.Size]byte) bool
 }
 
 func newScriptResultComparison(
 	log zerolog.Logger,
 	metrics module.BackendScriptsMetrics,
+	shouldLogScript func(time.Time, [md5.Size]byte) bool,
 	request *scriptExecutionRequest,
 ) *scriptResultComparison {
 	return &scriptResultComparison{
-		log:     log,
-		metrics: metrics,
-		request: request,
+		log:             log,
+		metrics:         metrics,
+		request:         request,
+		shouldLogScript: shouldLogScript,
 	}
 }
 
@@ -66,7 +72,7 @@ func (c *scriptResultComparison) compare(execResult, localResult *scriptResult)
 
 		c.metrics.ScriptExecutionErrorMismatch()
 		c.logComparison(execResult, localResult,
-			"cadence errors from local execution do not match EN", true)
+			"cadence errors from local execution do not match EN", logDiffAsError)
 		return false
 	}
 
@@ -77,7 +83,7 @@ func (c *scriptResultComparison) compare(execResult, localResult *scriptResult)
 
 	c.metrics.ScriptExecutionResultMismatch()
 	c.logComparison(execResult, localResult,
-		"script execution results from local execution do not match EN", true)
+		"script execution results from local execution do not match EN", logDiffAsError)
 	return false
 }
 
@@ -91,20 +97,23 @@ func (c *scriptResultComparison) logComparison(execResult, localResult *scriptRe
 	lgCtx := c.log.With().
 		Hex("block_id", c.request.blockID[:]).
 		Hex("script_hash", c.request.insecureScriptHash[:]).
-		Str("script", string(c.request.script)).
 		Strs("args", args)
 
+	if c.shouldLogScript(time.Now(), c.request.insecureScriptHash) {
+		lgCtx = lgCtx.Str("script", string(c.request.script))
+	}
+
 	if execResult.err != nil {
 		lgCtx = lgCtx.AnErr("execution_node_error", execResult.err)
 	} else {
-		lgCtx = lgCtx.Hex("execution_node_result", execResult.result)
+		lgCtx = lgCtx.Str("execution_node_result", base64.StdEncoding.EncodeToString(execResult.result))
 	}
 	lgCtx = lgCtx.Dur("execution_node_duration_ms", execResult.duration)
 
 	if localResult.err != nil {
 		lgCtx = lgCtx.AnErr("local_error", localResult.err)
 	} else {
-		lgCtx = lgCtx.Hex("local_result", localResult.result)
+		lgCtx = lgCtx.Str("local_result", base64.StdEncoding.EncodeToString(localResult.result))
 	}
 	lgCtx = lgCtx.Dur("local_duration_ms", localResult.duration)
 

engine/access/rpc/backend/script_comparer_test.go

@@ -3,6 +3,7 @@ package backend
 import (
 	"fmt"
 	"testing"
+	"time"
 
 	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/assert"
@@ -79,7 +80,8 @@ func TestCompare(t *testing.T) {
 	}
 
 	request := newScriptExecutionRequest(unittest.IdentifierFixture(), 1, []byte("script"), [][]byte{})
-	comparer := newScriptResultComparison(logger, m, request)
+	shouldLogScript := func(time.Time, [16]byte) bool { return true }
+	comparer := newScriptResultComparison(logger, m, shouldLogScript, request)
 
 	for _, tc := range testcases {
 		t.Run(tc.name, func(t *testing.T) {