Skip to content

Commit

Permalink
Add parser for integration SDK errors
Browse files Browse the repository at this point in the history
  • Loading branch information
@alvarocabanas
alvarocabanas committed Feb 5, 2024
1 parent a2743ff commit d619854
Show file tree
Hide file tree
Showing 5 changed files with 244 additions and 17 deletions.
6 changes: 3 additions & 3 deletions go.mod
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ require (
github.com/antihax/optional v1.0.0
github.com/aws/aws-sdk-go v1.44.69
github.com/beevik/ntp v0.3.0
github.com/containerd/containerd v1.7.11
github.com/containerd/containerd v1.7.13
github.com/containerd/typeurl/v2 v2.1.1
github.com/coreos/go-systemd/v22 v22.5.0
github.com/docker/docker v24.0.7+incompatible
Expand All @@ -26,7 +26,7 @@ require (
github.com/newrelic/newrelic-telemetry-sdk-go v0.8.1
github.com/opencontainers/go-digest v1.0.0
github.com/opencontainers/image-spec v1.1.0-rc2.0.20221005185240-3a7f492d3f1b
github.com/opencontainers/runtime-spec v1.1.0-rc.1
github.com/opencontainers/runtime-spec v1.1.0
github.com/pkg/errors v0.9.1
github.com/prometheus/procfs v0.8.0
github.com/shirou/gopsutil/v3 v3.21.11
Expand Down Expand Up @@ -73,10 +73,10 @@ require (
github.com/moby/sys/mountinfo v0.6.2 // indirect
github.com/moby/sys/sequential v0.5.0 // indirect
github.com/moby/sys/signal v0.7.0 // indirect
github.com/moby/sys/user v0.1.0 // indirect
github.com/moby/term v0.5.0 // indirect
github.com/morikuni/aec v1.0.0 // indirect
github.com/niemeyer/pretty v0.0.0-20200227124842-a10e7caefd8e // indirect
github.com/opencontainers/runc v1.1.6 // indirect
github.com/opencontainers/selinux v1.11.0 // indirect
github.com/pmezard/go-difflib v1.0.0 // indirect
github.com/power-devops/perfstat v0.0.0-20210106213030-5aafc221ea8c // indirect
Expand Down
12 changes: 6 additions & 6 deletions go.sum
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,8 +26,8 @@ github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDk
github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc=
github.com/containerd/cgroups v1.1.0 h1:v8rEWFl6EoqHB+swVNjVoCJE8o3jX7e8nqBGPLaDFBM=
github.com/containerd/cgroups v1.1.0/go.mod h1:6ppBcbh/NOOUU+dMKrykgaBnK9lCIBxHqJDGwsa1mIw=
github.com/containerd/containerd v1.7.11 h1:lfGKw3eU35sjV0aG2eYZTiwFEY1pCzxdzicHP3SZILw=
github.com/containerd/containerd v1.7.11/go.mod h1:5UluHxHTX2rdvYuZ5OJTC5m/KJNs0Zs9wVoJm9zf5ZE=
github.com/containerd/containerd v1.7.13 h1:wPYKIeGMN8vaggSKuV1X0wZulpMz4CrgEsZdaCyB6Is=
github.com/containerd/containerd v1.7.13/go.mod h1:zT3up6yTRfEUa6+GsITYIJNgSVL9NQ4x4h1RPzk0Wu4=
github.com/containerd/continuity v0.4.2 h1:v3y/4Yz5jwnvqPKJJ+7Wf93fyWoCB3F5EclWG023MDM=
github.com/containerd/continuity v0.4.2/go.mod h1:F6PTNCKepoxEaXLQp3wDAjygEnImnZ/7o4JzpodfroQ=
github.com/containerd/fifo v1.1.0 h1:4I2mbh5stb1u6ycIABlBw9zgtlK8viPI9QkQNRQEEmY=
Expand Down Expand Up @@ -143,6 +143,8 @@ github.com/moby/sys/sequential v0.5.0 h1:OPvI35Lzn9K04PBbCLW0g4LcFAJgHsvXsRyewg5
github.com/moby/sys/sequential v0.5.0/go.mod h1:tH2cOOs5V9MlPiXcQzRC+eEyab644PWKGRYaaV5ZZlo=
github.com/moby/sys/signal v0.7.0 h1:25RW3d5TnQEoKvRbEKUGay6DCQ46IxAVTT9CUMgmsSI=
github.com/moby/sys/signal v0.7.0/go.mod h1:GQ6ObYZfqacOwTtlXvcmh9A26dVRul/hbOZn88Kg8Tg=
github.com/moby/sys/user v0.1.0 h1:WmZ93f5Ux6het5iituh9x2zAG7NFY9Aqi49jjE1PaQg=
github.com/moby/sys/user v0.1.0/go.mod h1:fKJhFOnsCN6xZ5gSfbM6zaHGgDJMrqt9/reuj4T7MmU=
github.com/moby/term v0.5.0 h1:xt8Q1nalod/v7BqbG21f8mQPqH+xAaC9C3N3wfWbVP0=
github.com/moby/term v0.5.0/go.mod h1:8FzsFHVUBGZdbDsJw/ot+X+d5HLUbvklYLJ9uGfcI3Y=
github.com/morikuni/aec v1.0.0 h1:nP9CBfwrvYnBRgY6qfDQkygYDmYwOilePFkwzv4dU8A=
Expand All @@ -159,10 +161,8 @@ github.com/opencontainers/go-digest v1.0.0 h1:apOUWs51W5PlhuyGyz9FCeeBIOUDA/6nW8
github.com/opencontainers/go-digest v1.0.0/go.mod h1:0JzlMkj0TRzQZfJkVvzbP0HBR3IKzErnv2BNG4W4MAM=
github.com/opencontainers/image-spec v1.1.0-rc2.0.20221005185240-3a7f492d3f1b h1:YWuSjZCQAPM8UUBLkYUk1e+rZcvWHJmFb6i6rM44Xs8=
github.com/opencontainers/image-spec v1.1.0-rc2.0.20221005185240-3a7f492d3f1b/go.mod h1:3OVijpioIKYWTqjiG0zfF6wvoJ4fAXGbjdZuI2NgsRQ=
github.com/opencontainers/runc v1.1.6 h1:XbhB8IfG/EsnhNvZtNdLB0GBw92GYEFvKlhaJk9jUgA=
github.com/opencontainers/runc v1.1.6/go.mod h1:CbUumNnWCuTGFukNXahoo/RFBZvDAgRh/smNYNOhA50=
github.com/opencontainers/runtime-spec v1.1.0-rc.1 h1:wHa9jroFfKGQqFHj0I1fMRKLl0pfj+ynAqBxo3v6u9w=
github.com/opencontainers/runtime-spec v1.1.0-rc.1/go.mod h1:jwyrGlmzljRJv/Fgzds9SsS/C5hL+LL3ko9hs6T5lQ0=
github.com/opencontainers/runtime-spec v1.1.0 h1:HHUyrt9mwHUjtasSbXSMvs4cyFxh+Bll4AjJ9odEGpg=
github.com/opencontainers/runtime-spec v1.1.0/go.mod h1:jwyrGlmzljRJv/Fgzds9SsS/C5hL+LL3ko9hs6T5lQ0=
github.com/opencontainers/selinux v1.11.0 h1:+5Zbo97w3Lbmb3PeqQtpmTkMwsW5nRI3YaLpt7tQ7oU=
github.com/opencontainers/selinux v1.11.0/go.mod h1:E5dMC3VPuVvVHDYmi78qvhJp8+M586T4DlDRYpFkyec=
github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
Expand Down
43 changes: 43 additions & 0 deletions internal/integrations/v4/runner/group_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -409,3 +409,46 @@ func Test_parseLogrusFields(t *testing.T) {
})
}
}

//nolint:paralleltest
func Test_parseSDKFields(t *testing.T) {
tests := map[string]struct {
input string
want logrus.Fields
}{
"debug": {`[DEBUG] Temperature changes`, logrus.Fields{
"level": `debug`,
"msg": `Temperature changes`,
}},
"info": {`[INFO] A group of walrus emerges from the ocean`, logrus.Fields{
"level": `info`,
"msg": `A group of walrus emerges from the ocean`,
}},
"fatal": {`[FATAL] The ice breaks!`, logrus.Fields{
"level": `fatal`,
"msg": `The ice breaks!`,
}},
"error": {`[ERR] Error creating connection to SQL Server: lookup mssql on 192.168.65.5:53: no such host`, logrus.Fields{
"level": `error`,
"msg": `Error creating connection to SQL Server: lookup mssql on 192.168.65.5:53: no such host`,
}},
"with-escaped-quotes": {`[WARN] The group's number \"increased\" tremendously!`, logrus.Fields{
"level": `warn`,
"msg": `The group's number \"increased\" tremendously!`,
}},

"not matching": {`simple line`, nil},
}

for name, tc := range tests {
t.Run(name, func(t *testing.T) {
out := parseSDKFields(tc.input)

for k, v := range tc.want {
val, ok := out[k]
assert.True(t, ok)
assert.Equal(t, v, val)
}
})
}
}
59 changes: 51 additions & 8 deletions internal/integrations/v4/runner/runner.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@ var (
//2- map: &{any character}
//3- word: any character except spaces
logrusRegexp = regexp.MustCompile(`([^\s]*?)=(".*?[^\\]"|&{.*?}|[^\s]*)`)
sdkLogRegexp = regexp.MustCompile(`\[([^\]]*)\]\s*(.+)`)
)

// generic types to handle the stderr log parsing
Expand All @@ -56,7 +57,7 @@ type runner struct {
log log.Entry
definition integration.Definition
handleErrors func(context.Context, <-chan error) // by default, runner.logErrors. Replaceable for testing purposes
stderrParser logParser
stderrParser []logParser
lastStderr stderrQueue
healthCheck sync.Once
heartBeatFunc func()
Expand Down Expand Up @@ -85,7 +86,7 @@ func NewRunner(
dSources: dSources,
definition: intDef,
heartBeatFunc: func() {},
stderrParser: parseLogrusFields,
stderrParser: []logParser{parseSDKFields, parseLogrusFields},
lastStderr: newStderrQueue(intDef.LogsQueueSize),
terminateQueue: terminateQ,
cache: cache.CreateCache(),
Expand Down Expand Up @@ -298,17 +299,40 @@ func (r *runner) handleStderr(stderr <-chan []byte) {

// obfuscated stderr
obfuscatedLine := helpers.ObfuscateSensitiveDataFromString(string(line))
var lineWasParsed bool

if r.log.IsDebugEnabled() {
r.log.WithField("line", obfuscatedLine).Debug("Integration stderr (not parsed).")
} else {
fields := r.stderrParser(obfuscatedLine)
if v, ok := fields["level"]; ok && (v == "error" || v == "fatal") {
for _, errParser := range r.stderrParser {
fields := errParser(obfuscatedLine)

if lvl, ok := fields["level"]; ok {
// If a field already exists, like the time, logrus automatically adds the prefix "deps." to the
// Duplicated keys
r.log.WithFields(logrus.Fields(fields)).Info("received an integration log line")
logLine := r.log.WithFields(logrus.Fields(fields))
logMessage := "integration log"

lvl, ok := lvl.(string)
if ok {
switch strings.ToLower(lvl) {
case "info", "debug":
logLine.Debug(logMessage)
case "trace":
logLine.Trace(logMessage)
case "warn", "warning":
logLine.Warn(logMessage)
default:
logLine.Error(logMessage)
}

lineWasParsed = true

break
}
}
}

if !lineWasParsed {
r.log.WithField("line", obfuscatedLine).Debug("Integration stderr (not parsed).")
}
}
}

Expand Down Expand Up @@ -429,3 +453,22 @@ func parseLogrusFields(line string) (fields logFields) {

return
}

func parseSDKFields(line string) logFields {
matches := sdkLogRegexp.FindAllStringSubmatch(line, -1)
if len(matches) == 0 {
return nil
}

lvl, msg := matches[0][1], matches[0][2]

level := strings.ToLower(lvl)
if level == "err" {
level = "error"
}

return logFields{
"level": level,
"msg": msg,
}
}
141 changes: 141 additions & 0 deletions internal/integrations/v4/runner/runner_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -185,3 +185,144 @@ func Test_runner_Run_handlesCfgProtocol(t *testing.T) {
return false
}, time.Second, 10*time.Millisecond)
}

//nolint:exhaustruct,funlen
func Test_runner_Run_Integration_Log(t *testing.T) {
t.Parallel()

if runtime.GOOS == "windows" {
t.Skip()
}

log.SetOutput(ioutil.Discard) // discard logs so not to break race tests
t.Cleanup(func() { log.SetOutput(os.Stderr) }) // return back to default

hook := new(test.Hook)
log.AddHook(hook)

log.SetLevel(logrus.TraceLevel)

testCases := []struct {
name string
logLine string
expectedLogMsg string
expectedLevel logrus.Level
}{
{
name: "SDK_Info_log",
logLine: "[INFO] This is an info message",
expectedLogMsg: "This is an info message",
expectedLevel: logrus.DebugLevel,
},
{
name: "SDK_Debug_log",
logLine: "[DEBUG] This is a debug message",
expectedLogMsg: "This is a debug message",
expectedLevel: logrus.DebugLevel,
},
{
name: "SDK_Trace_log",
logLine: "[TRACE] This is a trace message",
expectedLogMsg: "This is a trace message",
expectedLevel: logrus.TraceLevel,
},
{
name: "SDK_Warning_log",
logLine: "[WARN] This is a warning message",
expectedLogMsg: "This is a warning message",
expectedLevel: logrus.WarnLevel,
},
{
name: "SDK_Error_log",
logLine: "[ERR] This is an error message",
expectedLogMsg: "This is an error message",
expectedLevel: logrus.ErrorLevel,
},
{
name: "SDK_Fatal_log",
logLine: "[FATAL] This is a fatal message",
expectedLogMsg: "This is a fatal message",
expectedLevel: logrus.ErrorLevel,
},
{
name: "Logrus_Info_log",
logLine: "level=info msg=\"This is an info message\"",
expectedLogMsg: "This is an info message",
expectedLevel: logrus.DebugLevel,
},
{
name: "Logrus_Debug_log",
logLine: "level=debug msg=\"This is a debug message\"",
expectedLogMsg: "This is a debug message",
expectedLevel: logrus.DebugLevel,
},
{
name: "Logrus_Trace_log",
logLine: "level=trace msg=\"This is a trace message\"",
expectedLogMsg: "This is a trace message",
expectedLevel: logrus.TraceLevel,
},
{
name: "Logrus_Warning_log",
logLine: "level=warning msg=\"This is a warning message\"",
expectedLogMsg: "This is a warning message",
expectedLevel: logrus.WarnLevel,
},
{
name: "Logrus_Error_log",
logLine: "level=error msg=\"This is an error message\"",
expectedLogMsg: "This is an error message",
expectedLevel: logrus.ErrorLevel,
},
{
name: "Logrus_Fatal_log",
logLine: "level=fatal msg=\"This is a fatal message\"",
expectedLogMsg: "This is a fatal message",
expectedLevel: logrus.ErrorLevel,
},
{
name: "Obfuscated_log",
logLine: "This is a parser-orphan log",
expectedLogMsg: "Integration stderr (not parsed).",
expectedLevel: logrus.DebugLevel,
},
}

for _, tt := range testCases {
testCase := tt
t.Run(testCase.name, func(t *testing.T) {
t.Parallel()
// GIVEN a runner that receives a cfg request without a handle function.
def, err := integration.NewDefinition(config.ConfigEntry{
InstanceName: testCase.name,
Exec: testhelp.Command(fixtures.EchoFromEnv),
Env: map[string]string{"STDERR_STRING": testCase.logLine},
}, integration.ErrLookup, nil, nil)
require.NoError(t, err)

e := &testemit.RecordEmitter{}
r := NewRunner(def, e, nil, nil, cmdrequest.NoopHandleFn, nil, nil, host.IDLookup{})

// WHEN the runner executes the binary and handle the payload.
ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond)
t.Cleanup(func() { cancel() })
r.Run(ctx, nil, nil)

var lastEntry *logrus.Entry
// THEN log entry found.
assert.Eventually(t, func() bool {
entries := hook.AllEntries()
for _, e := range entries {
if e.Data["msg"] == testCase.expectedLogMsg || e.Message == testCase.expectedLogMsg {
lastEntry = e

return true
}
}

return false
}, time.Second, 100*time.Millisecond)
assert.Equal(t, testCase.expectedLevel, lastEntry.Level)
})
}
}

0 comments on commit d619854

Please sign in to comment.