Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Access] Reduce logging for script executions #5959

Merged
merged 3 commits into from
Jul 5, 2024
Merged

[Access] Reduce logging for script executions #5959

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
4b213f0
[Access] Reduce logging for script executions
peterargue May 21, 2024
a21d2f3
fix unittest
peterargue May 21, 2024
087b11e
undo error formatting change
peterargue May 21, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 25 additions & 20 deletions engine/access/rpc/backend/backend_scripts.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand All @@ -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),
Expand Down Expand Up @@ -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")
Expand All @@ -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")
Expand Down Expand Up @@ -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,
Expand All @@ -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
}
Comment on lines 250 to 252
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not a part of your diff, but we should move this up to immediately after the error is returned, on line 246.


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
Expand All @@ -266,10 +267,11 @@ func (b *backendScripts) executeScriptOnAvailableExecutionNodes(
},
func(node *flow.IdentitySkeleton, 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
Expand Down Expand Up @@ -318,6 +320,9 @@ func isInvalidArgumentError(scriptExecutionErr error) bool {

// shouldLogScript checks if the script hash is unique in the time window
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
// shouldLogScript checks if the script hash is unique in the time window
// shouldLogScript checks whether we should log a script, based on whether we have seen it recently
// and the current log level.

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
Expand Down
31 changes: 20 additions & 11 deletions engine/access/rpc/backend/script_comparer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@ package backend

import (
"bytes"
"crypto/md5" //nolint:gosec
"encoding/base64"
"strings"
"time"

Expand All @@ -14,6 +16,7 @@ import (

const (
executeErrorPrefix = "failed to execute script at block"
logDiffAsError = false
)

type scriptResult struct {
Expand All @@ -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,
}
}

Expand All @@ -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
}

Expand All @@ -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
}

Expand All @@ -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)

Expand Down
4 changes: 3 additions & 1 deletion engine/access/rpc/backend/script_comparer_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package backend
import (
"fmt"
"testing"
"time"

"github.com/rs/zerolog"
"github.com/stretchr/testify/assert"
Expand Down Expand Up @@ -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) {
Expand Down
Loading