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

rpc: truncate call error data logs #30028

Merged
merged 5 commits into from
Jun 28, 2024
+39 −6
Merged

rpc: truncate call error data logs #30028

Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
e012d41
rpc: truncate call error data logs
ceyonur Jun 19, 2024
7f6283e
rpc: fix typo
ceyonur Jun 19, 2024
a15b9c8
rpc: truncate errdata at all log levels
ceyonur Jun 20, 2024
5f1cbce
rpc: fix truncate comment
ceyonur Jun 20, 2024
441e100
rpc: json-encode error data in log
fjl Jun 28, 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
29 changes: 23 additions & 6 deletions rpc/handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ package rpc
import (
"context"
"encoding/json"
"fmt"
"reflect"
"strconv"
"strings"
Expand All @@ -28,6 +29,9 @@ import (
"github.com/ethereum/go-ethereum/log"
)

// callErrorDataLogTruncateLimit is the before truncation limit of the error data field in the log.
const callErrorDataLogTruncateLimit = 1024

// handler handles JSON-RPC messages. There is one handler per connection. Note that
// handler is not safe for concurrent use. Message handling never blocks indefinitely
// because RPCs are processed on background goroutines launched by handler.
Expand Down Expand Up @@ -468,16 +472,29 @@ func (h *handler) handleCallMsg(ctx *callProc, msg *jsonrpcMessage) *jsonrpcMess

case msg.isCall():
resp := h.handleCall(ctx, msg)
var ctx []interface{}
ctx = append(ctx, "reqid", idForLog{msg.ID}, "duration", time.Since(start))
var logCtx []interface{}
logCtx = append(logCtx, "reqid", idForLog{msg.ID}, "duration", time.Since(start))
if resp.Error != nil {
ctx = append(ctx, "err", resp.Error.Message)
logCtx = append(logCtx, "err", resp.Error.Message)
if resp.Error.Data != nil {
ctx = append(ctx, "errdata", resp.Error.Data)
// If the log level is debug, log the full error data. Otherwise, try to truncate it.
Copy link
Member

Choose a reason for hiding this comment

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

Is this the right value to branch on ? Do rpc runners not run nodes with log level >= debug? I feel like we should either unilaterally truncate the error data in the log or have a separate flag to control error truncation.

I lean towards unilaterally truncating.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think we should let debug level logger to show full logs without truncating to actually see the full error (probably in case after seeing truncated logs).

I was under impression rpc nodes would run with Info/Warn (not debug).

Copy link
Member

Choose a reason for hiding this comment

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

As an RPC node, it feels unexpected that it's "safe" for me to expose my endpoint if my log level is below debug, but once I hit debug it is not longer "safe".

Copy link
Contributor Author

Choose a reason for hiding this comment

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

true, and that branch truncates logs if the log level > debug (warn, info) which is safe (if I'm not missing something else). log.Enabled(context.Background(), log.LvlDebug) would return true if the logger is operating at debug or below (trace). otherwise we will truncate it (if info/warn).

It might be a bit strange to see different outputs (non-truncated) for a Warn log when you switch to debug, but I can't think a better way to present the full non-truncated err data. Alternatively maybe we can print both a warn message with truncated data and then a debug message with non-truncated data.

Copy link
Contributor

@fjl fjl Jun 20, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

I didn't even know we print the error data in full in the first place. It seems to have been added in #21083. Really don't think it's necessary to preserve the full data in logs, since they are just for debugging failed calls. So let's just always truncate the data.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

removed the debug lvl condition

if h.log.Enabled(context.Background(), log.LvlDebug) {
logCtx = append(logCtx, "errdata", resp.Error.Data)
} else {
errDataStr := fmt.Sprintf("%v", resp.Error.Data)
// Truncate the error data if it is too long. Otherwise, preserve the original data.
if len(errDataStr) > callErrorDataLogTruncateLimit {
remaining := len(errDataStr) - callErrorDataLogTruncateLimit
errDataStr = fmt.Sprintf("%s... (truncated remaining %d chars)", errDataStr[:callErrorDataLogTruncateLimit], remaining)
logCtx = append(logCtx, "errdata", errDataStr)
} else {
logCtx = append(logCtx, "errdata", resp.Error.Data)
}
}
}
h.log.Warn("Served "+msg.Method, ctx...)
h.log.Warn("Served "+msg.Method, logCtx...)
} else {
h.log.Debug("Served "+msg.Method, ctx...)
h.log.Debug("Served "+msg.Method, logCtx...)
}
return resp

Expand Down