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.

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

[pkg/stanza] Improve error logs produced by transformer processors #37285

Merged
Merged
Show file tree
Hide file tree
Changes from 8 commits
Commits
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: 29 additions & 0 deletions .chloggen/improve-log-transformers-logs.yaml
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
# Use this changelog template to create an entry for release notes.

# One of 'breaking', 'deprecation', 'new_component', 'enhancement', 'bug_fix'
change_type: enhancement

# The name of the component, or a single word describing the area of concern, (e.g. filelogreceiver)
component: pkg/stanza

# A brief description of the change. Surround your text with quotes ("") if it needs to start with a backtick (`).
note: Add log file path and original record to errors logs from log transformers processors

# Mandatory: One or more tracking issues related to the change. You can use the PR number here if no issue exists.
issues: [37285]

# (Optional) One or more lines of additional information to render under the primary note.
# These lines will be padded with 2 spaces and then inserted directly into the document.
# Use pipe (|) for multiline entries.
subtext: |
When a log transformer processor fails to process an log entry it will include the log file path and the entry's body in its own logs.
This makes it easier to debug why certain log entries are causing issues in the processors.

# If your change doesn't affect end users or the exported elements of any package,
# you should instead start your pull request title with [chore] or use the "Skip Changelog" label.
# Optional: The change log or logs in which this entry should be included.
# e.g. '[user]' or '[user, api]'
# Include 'user' if the change is relevant to end users.
# Include 'api' if there is a change to a library API.
# Default: '[user]'
change_logs: [user]
1 change: 1 addition & 0 deletions pkg/stanza/fileconsumer/attrs/attrs.go
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ const (
LogFileOwnerName = "log.file.owner.name"
LogFileOwnerGroupName = "log.file.owner.group.name"
LogFileRecordNumber = "log.file.record_number"
LogRecordOriginal = "log.record.original"
)

type Resolver struct {
Expand Down
18 changes: 16 additions & 2 deletions pkg/stanza/operator/helper/transformer.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,13 +6,15 @@ package helper // import "github.com/open-telemetry/opentelemetry-collector-cont
import (
"context"
"fmt"
"slices"

"github.com/expr-lang/expr/vm"
"go.opentelemetry.io/collector/component"
"go.uber.org/zap"

"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/entry"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/errors"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/attrs"
)

// NewTransformerConfig creates a new transformer config with default values
Expand Down Expand Up @@ -94,10 +96,22 @@ func (t *TransformerOperator) ProcessWith(ctx context.Context, entry *entry.Entr

// HandleEntryError will handle an entry error using the on_error strategy.
func (t *TransformerOperator) HandleEntryError(ctx context.Context, entry *entry.Entry, err error) error {
logFields := []zap.Field{
zap.Any("error", err),
zap.Any("action", t.OnError),
}
if entry != nil {
toAddFields := []zap.Field{zap.Any(attrs.LogRecordOriginal, entry.Body)}
Copy link
Member

Choose a reason for hiding this comment

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

I don't agree we should add the body. The body could contain sensitive information and is not necessarily the reason for the failure. Maybe the timestamp is enough?

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 wanted to make the Collector's log useful enough so that we could avoid looking at the real log file.

I had totally overlooked the fact that the body can contain sensitive information. So I agree that we can't simply include it there. :/

Originally I wanted to include the line number of the entry, but because of the way the file scanning is working it got complicated (lots of wrapping of the scanner's splitfunc and some file position tracking is byte based instead of line based).

I think the timestamp will be a good substitute for now and I can try to get the line number working later. 👍

if logFilePath, ok := entry.Attributes[attrs.LogFilePath]; ok {
toAddFields = slices.Insert(toAddFields, 0, zap.Any(attrs.LogFilePath, logFilePath))
}
logFields = slices.Insert(logFields, 0, toAddFields...)
}

if t.OnError == SendOnErrorQuiet || t.OnError == DropOnErrorQuiet {
t.Logger().Debug("Failed to process entry", zap.Any("error", err), zap.Any("action", t.OnError))
t.Logger().Debug("Failed to process entry", logFields...)
} else {
t.Logger().Error("Failed to process entry", zap.Any("error", err), zap.Any("action", t.OnError))
t.Logger().Error("Failed to process entry", logFields...)
}
if t.OnError == SendOnError || t.OnError == SendOnErrorQuiet {
writeErr := t.Write(ctx, entry)
Expand Down
19 changes: 18 additions & 1 deletion pkg/stanza/operator/helper/transformer_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ import (
"go.uber.org/zap/zaptest/observer"

"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/entry"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/attrs"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/testutil"
)
Expand Down Expand Up @@ -91,6 +92,8 @@ func TestTransformerDropOnError(t *testing.T) {
}
ctx := context.Background()
testEntry := entry.New()
testEntry.Body = "test"
testEntry.AddAttribute(attrs.LogFilePath, "/test/file")
transform := func(_ *entry.Entry) error {
return fmt.Errorf("Failure")
}
Expand All @@ -104,7 +107,9 @@ func TestTransformerDropOnError(t *testing.T) {
{
Entry: zapcore.Entry{Level: zap.ErrorLevel, Message: "Failed to process entry"},
Context: []zapcore.Field{
{Key: "error", Type: 26, Interface: fmt.Errorf("Failure")},
zap.Any(attrs.LogFilePath, "/test/file"),
zap.Any(attrs.LogRecordOriginal, "test"),
{Key: "error", Type: zapcore.ErrorType, Interface: fmt.Errorf("Failure")},
zap.Any("action", "drop"),
},
},
Expand Down Expand Up @@ -136,6 +141,8 @@ func TestTransformerDropOnErrorQuiet(t *testing.T) {
}
ctx := context.Background()
testEntry := entry.New()
testEntry.Body = "test"
testEntry.AddAttribute(attrs.LogFilePath, "/test/file")
transform := func(_ *entry.Entry) error {
return fmt.Errorf("Failure")
}
Expand All @@ -149,6 +156,8 @@ func TestTransformerDropOnErrorQuiet(t *testing.T) {
{
Entry: zapcore.Entry{Level: zap.DebugLevel, Message: "Failed to process entry"},
Context: []zapcore.Field{
zap.Any(attrs.LogFilePath, "/test/file"),
zap.Any(attrs.LogRecordOriginal, "test"),
{Key: "error", Type: 26, Interface: fmt.Errorf("Failure")},
zap.Any("action", "drop_quiet"),
},
Expand Down Expand Up @@ -181,6 +190,8 @@ func TestTransformerSendOnError(t *testing.T) {
}
ctx := context.Background()
testEntry := entry.New()
testEntry.Body = "test"
testEntry.AddAttribute(attrs.LogFilePath, "/test/file")
transform := func(_ *entry.Entry) error {
return fmt.Errorf("Failure")
}
Expand All @@ -194,6 +205,8 @@ func TestTransformerSendOnError(t *testing.T) {
{
Entry: zapcore.Entry{Level: zap.ErrorLevel, Message: "Failed to process entry"},
Context: []zapcore.Field{
zap.Any(attrs.LogFilePath, "/test/file"),
zap.Any(attrs.LogRecordOriginal, "test"),
{Key: "error", Type: 26, Interface: fmt.Errorf("Failure")},
zap.Any("action", "send"),
},
Expand Down Expand Up @@ -226,6 +239,8 @@ func TestTransformerSendOnErrorQuiet(t *testing.T) {
}
ctx := context.Background()
testEntry := entry.New()
testEntry.Body = "test"
testEntry.AddAttribute(attrs.LogFilePath, "/test/file")
transform := func(_ *entry.Entry) error {
return fmt.Errorf("Failure")
}
Expand All @@ -239,6 +254,8 @@ func TestTransformerSendOnErrorQuiet(t *testing.T) {
{
Entry: zapcore.Entry{Level: zap.DebugLevel, Message: "Failed to process entry"},
Context: []zapcore.Field{
zap.Any(attrs.LogFilePath, "/test/file"),
zap.Any(attrs.LogRecordOriginal, "test"),
{Key: "error", Type: 26, Interface: fmt.Errorf("Failure")},
zap.Any("action", "send_quiet"),
},
Expand Down
17 changes: 14 additions & 3 deletions pkg/stanza/operator/transformer/router/transformer.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,11 +6,13 @@ package router // import "github.com/open-telemetry/opentelemetry-collector-cont
import (
"context"
"fmt"
"slices"

"github.com/expr-lang/expr/vm"
"go.uber.org/zap"

"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/entry"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/attrs"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator"
"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper"
)
Expand Down Expand Up @@ -39,24 +41,33 @@ func (t *Transformer) Process(ctx context.Context, entry *entry.Entry) error {
env := helper.GetExprEnv(entry)
defer helper.PutExprEnv(env)

logger := t.Logger()
if entry != nil {
toAddFields := []zap.Field{zap.Any(attrs.LogRecordOriginal, entry.Body)}
if logFilePath, ok := entry.Attributes[attrs.LogFilePath]; ok {
toAddFields = slices.Insert(toAddFields, 0, zap.Any(attrs.LogFilePath, logFilePath))
}
logger = logger.With(toAddFields...)
}

for _, route := range t.routes {
matches, err := vm.Run(route.Expression, env)
if err != nil {
t.Logger().Warn("Running expression returned an error", zap.Error(err))
logger.Warn("Running expression returned an error", zap.Error(err))
continue
}

// we compile the expression with "AsBool", so this should be safe
if matches.(bool) {
if err = route.Attribute(entry); err != nil {
t.Logger().Error("Failed to label entry", zap.Error(err))
logger.Error("Failed to label entry", zap.Error(err))
return err
}

for _, output := range route.OutputOperators {
err = output.Process(ctx, entry)
if err != nil {
t.Logger().Error("Failed to process entry", zap.Error(err))
logger.Error("Failed to process entry", zap.Error(err))
}
}
break
Expand Down
Loading