From e012d411b53d523f8f1604c6f008407e71c2df7c Mon Sep 17 00:00:00 2001 From: Ceyhun Onur Date: Wed, 19 Jun 2024 19:03:04 +0300 Subject: [PATCH 1/5] rpc: truncate call error data logs --- rpc/handler.go | 29 +++++++++++++++++++++++------ 1 file changed, 23 insertions(+), 6 deletions(-) diff --git a/rpc/handler.go b/rpc/handler.go index 7b8f64aa7be8..af6ff7b1d73a 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -19,6 +19,7 @@ package rpc import ( "context" "encoding/json" + "fmt" "reflect" "strconv" "strings" @@ -28,6 +29,9 @@ import ( "github.com/ethereum/go-ethereum/log" ) +// callErrorDataLogDTruncateLimit 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. @@ -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. + 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 From 7f6283e10a2c3b74e7b8b07413be0ac80b7c20ab Mon Sep 17 00:00:00 2001 From: Ceyhun Onur Date: Wed, 19 Jun 2024 19:05:18 +0300 Subject: [PATCH 2/5] rpc: fix typo --- rpc/handler.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rpc/handler.go b/rpc/handler.go index af6ff7b1d73a..e0fe8e7cd606 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -29,7 +29,7 @@ import ( "github.com/ethereum/go-ethereum/log" ) -// callErrorDataLogDTruncateLimit is the before truncation limit of the error data field in the 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 From a15b9c88cb148488aae05b375943d9eec4b8d255 Mon Sep 17 00:00:00 2001 From: Ceyhun Onur Date: Thu, 20 Jun 2024 18:40:38 +0300 Subject: [PATCH 3/5] rpc: truncate errdata at all log levels --- rpc/handler.go | 19 +++++++------------ 1 file changed, 7 insertions(+), 12 deletions(-) diff --git a/rpc/handler.go b/rpc/handler.go index e0fe8e7cd606..14dbbca62389 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -477,19 +477,14 @@ func (h *handler) handleCallMsg(ctx *callProc, msg *jsonrpcMessage) *jsonrpcMess if resp.Error != nil { logCtx = append(logCtx, "err", resp.Error.Message) if resp.Error.Data != nil { - // If the log level is debug, log the full error data. Otherwise, try to truncate it. - if h.log.Enabled(context.Background(), log.LvlDebug) { - logCtx = append(logCtx, "errdata", resp.Error.Data) + errDataStr := fmt.Sprintf("%v", resp.Error.Data) + // Truncate the error data as string 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 { - 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) - } + logCtx = append(logCtx, "errdata", resp.Error.Data) } } h.log.Warn("Served "+msg.Method, logCtx...) From 5f1cbceb6b30155246fde18fe9d72f4066bc8a71 Mon Sep 17 00:00:00 2001 From: Ceyhun Onur Date: Thu, 20 Jun 2024 18:42:57 +0300 Subject: [PATCH 4/5] rpc: fix truncate comment --- rpc/handler.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rpc/handler.go b/rpc/handler.go index 14dbbca62389..624342adcde0 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -478,7 +478,7 @@ func (h *handler) handleCallMsg(ctx *callProc, msg *jsonrpcMessage) *jsonrpcMess logCtx = append(logCtx, "err", resp.Error.Message) if resp.Error.Data != nil { errDataStr := fmt.Sprintf("%v", resp.Error.Data) - // Truncate the error data as string if it is too long. Otherwise, preserve the original 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) From 441e10095574b7776408a8ae77cd532d6d2b4dd6 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Fri, 28 Jun 2024 16:17:18 +0200 Subject: [PATCH 5/5] rpc: json-encode error data in log --- rpc/handler.go | 55 ++++++++++++++++++++++++++++++++++---------------- 1 file changed, 38 insertions(+), 17 deletions(-) diff --git a/rpc/handler.go b/rpc/handler.go index 624342adcde0..f23b544b5869 100644 --- a/rpc/handler.go +++ b/rpc/handler.go @@ -17,8 +17,10 @@ package rpc import ( + "bytes" "context" "encoding/json" + "errors" "fmt" "reflect" "strconv" @@ -29,9 +31,6 @@ 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. @@ -472,24 +471,16 @@ func (h *handler) handleCallMsg(ctx *callProc, msg *jsonrpcMessage) *jsonrpcMess case msg.isCall(): resp := h.handleCall(ctx, msg) - var logCtx []interface{} - logCtx = append(logCtx, "reqid", idForLog{msg.ID}, "duration", time.Since(start)) + var logctx []any + logctx = append(logctx, "reqid", idForLog{msg.ID}, "duration", time.Since(start)) if resp.Error != nil { - logCtx = append(logCtx, "err", resp.Error.Message) + logctx = append(logctx, "err", resp.Error.Message) if resp.Error.Data != nil { - 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) - } + logctx = append(logctx, "errdata", formatErrorData(resp.Error.Data)) } - h.log.Warn("Served "+msg.Method, logCtx...) + h.log.Warn("Served "+msg.Method, logctx...) } else { - h.log.Debug("Served "+msg.Method, logCtx...) + h.log.Debug("Served "+msg.Method, logctx...) } return resp @@ -603,3 +594,33 @@ func (id idForLog) String() string { } return string(id.RawMessage) } + +var errTruncatedOutput = errors.New("truncated output") + +type limitedBuffer struct { + output []byte + limit int +} + +func (buf *limitedBuffer) Write(data []byte) (int, error) { + avail := max(buf.limit, len(buf.output)) + if len(data) < avail { + buf.output = append(buf.output, data...) + return len(data), nil + } + buf.output = append(buf.output, data[:avail]...) + return avail, errTruncatedOutput +} + +func formatErrorData(v any) string { + buf := limitedBuffer{limit: 1024} + err := json.NewEncoder(&buf).Encode(v) + switch { + case err == nil: + return string(bytes.TrimRight(buf.output, "\n")) + case errors.Is(err, errTruncatedOutput): + return fmt.Sprintf("%s... (truncated)", buf.output) + default: + return fmt.Sprintf("bad error data (err=%v)", err) + } +}