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

Jump to bottom

VC-35738: Assert the logs in TestNoneCache #619

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
+95 −63
Open

VC-35738: Assert the logs in TestNoneCache #619

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
11 changes: 10 additions & 1 deletion pkg/datagatherer/k8s/cache_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,10 +8,12 @@ import (
"github.com/d4l3k/messagediff"
"github.com/go-logr/logr"
"github.com/pmylund/go-cache"
"github.com/stretchr/testify/assert"
"k8s.io/apimachinery/pkg/runtime"
"k8s.io/klog/v2/ktesting"

"github.com/jetstack/preflight/api"
"github.com/jetstack/preflight/pkg/testutil"
)

func makeGatheredResource(obj runtime.Object, deletedAt api.Time) *api.GatheredResource {
Expand Down Expand Up @@ -143,10 +145,17 @@ func TestOnAddCache(t *testing.T) {
// TestNoneCache demonstrates that the cache helpers do not crash if passed a
// non-cachable object, but log an error with a reference to the object type.
func TestNoneCache(t *testing.T) {
log := ktesting.NewLogger(t, ktesting.NewConfig(ktesting.Verbosity(10)))
var buffer ktesting.BufferTL
log := ktesting.NewLogger(&buffer, ktesting.NewConfig(ktesting.Verbosity(10)))

type notCachable struct{}
onAdd(log, &notCachable{}, nil)
onUpdate(log, &notCachable{}, nil, nil)
onDelete(log, &notCachable{}, nil)

assert.Equal(t, testutil.Undent(`
E0000 00:00:00.000000] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="add"
E0000 00:00:00.000000] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="update"
E0000 00:00:00.000000] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="delete"
`), testutil.ReplaceWithStaticTimestamps(buffer.String()))
}
Copy link
Member

Choose a reason for hiding this comment

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

In config_test I used ktesting like this:

jetstack-secure/pkg/agent/config_test.go

Lines 998 to 1003 in 1a567ef

func recordLogs(t *testing.T) (logr.Logger, ktesting.Buffer) {
log := ktesting.NewLogger(t, ktesting.NewConfig(ktesting.BufferLogs(true)))
testingLogger, ok := log.GetSink().(ktesting.Underlier)
require.True(t, ok)
return log, testingLogger.GetBuffer()
} 

// TestNoneCache demonstrates that the cache helpers do not crash if passed a
// non-cachable object, but log an error with a reference to the object type.
func TestNoneCache(t *testing.T) {
	log := ktesting.NewLogger(t, ktesting.NewConfig(ktesting.Verbosity(10), ktesting.BufferLogs(true)))
	testingLogger, ok := log.GetSink().(ktesting.Underlier)
	require.True(t, ok)
	buffer := testingLogger.GetBuffer()
	type notCachable struct{}
	onAdd(log, &notCachable{}, nil)
	onUpdate(log, &notCachable{}, nil, nil)
	onDelete(log, &notCachable{}, nil)
	assert.Equal(t, testutil.Undent(`
		ERROR Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="add"
		ERROR Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="update"
		ERROR Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="delete"
        `), buffer.String())
}

The advantage is that you don't have to worry about timestamps in the logs; you only assert that the logged messages have the expected severity and that the message and additional structured fields are visible.

An additional advantage, and the real reason I created this test, was to be able to see and verify that the correct line numbers were being logged.

$ go test ./pkg/datagatherer/k8s/... -run TestNoneCache -v
=== RUN   TestNoneCache
    cache.go:53: E1115 09:54:01.716188] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="add"
    cache.go:66: E1115 09:54:01.716256] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="update"
    cache.go:80: E1115 09:54:01.716376] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="delete"
--- PASS: TestNoneCache (0.00s)
PASS
ok      github.com/jetstack/preflight/pkg/datagatherer/k8s      0.032s

I had forgotten to use the WithHelper modifier in the logging helper function and the go test -v output helped me get that right.

jetstack-secure/pkg/datagatherer/k8s/cache.go

Lines 34 to 40 in 1a567ef

func logCacheUpdateFailure(log logr.Logger, obj interface{}, operation string) {
// We use WithCallStackHelper to ensure the correct caller line numbers in the log messages
helper, log := log.WithCallStackHelper()
helper()
err := fmt.Errorf("not a cacheResource type: %T missing metadata/uid field", obj)
log.Error(err, "Cache update failure", "operation", operation)
}

65 changes: 3 additions & 62 deletions pkg/logs/logs_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,6 @@ import (
"log/slog"
"os"
"os/exec"
"regexp"
"strings"
"testing"
"time"
Expand All @@ -22,6 +21,7 @@ import (
"k8s.io/klog/v2"

"github.com/jetstack/preflight/pkg/logs"
"github.com/jetstack/preflight/pkg/testutil"
)

// TestLogs demonstrates how the logging flags affect the logging output.
Expand Down Expand Up @@ -307,67 +307,8 @@ E0000 00:00:00.000000 00000 logs_test.go:000] "Contextual error" err="fake-err
test.expectStdout = strings.TrimPrefix(test.expectStdout, "\n")
test.expectStderr = strings.TrimPrefix(test.expectStderr, "\n")

require.Equal(t, test.expectStdout, replaceWithStaticTimestamps(stdoutStr), "stdout doesn't match")
require.Equal(t, test.expectStderr, replaceWithStaticTimestamps(stderrStr), "stderr doesn't match")
})
}
}

var (
timestampRegexpStdLog = regexp.MustCompile(`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}`)
timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} +\d+`)
timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.?\d*`)
fileAndLineRegexpJSON = regexp.MustCompile(`"caller":"([^"]+).go:\d+"`)
fileAndLineRegexpKlog = regexp.MustCompile(` ([^:]+).go:\d+`)
)

// Replaces the klog and JSON timestamps with a static timestamp to make it
// easier to assert the logs. It also replaces the line number with 000 as it
// often changes.
//
// I1018 15:12:57.953433 22183 logs.go:000] log
// {"ts":1729258473588.828,"caller":"log/log.go:000","msg":"log Print","v":0}
// 2024/10/18 15:40:50 log Print
//
// to the fixed:
//
// I0000 00:00:00.000000 00000 logs.go:000] log
// {"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
// 0000/00/00 00:00:00 log Print
func replaceWithStaticTimestamps(input string) string {
input = timestampRegexpKlog.ReplaceAllString(input, "0000 00:00:00.000000 00000")
input = timestampRegexpJSON.ReplaceAllString(input, `"ts":0000000000000.000`)
input = timestampRegexpStdLog.ReplaceAllString(input, "0000/00/00 00:00:00")
input = fileAndLineRegexpJSON.ReplaceAllString(input, `"caller":"$1.go:000"`)
input = fileAndLineRegexpKlog.ReplaceAllString(input, " $1.go:000")
return input
}

func Test_replaceWithStaticTimestamps(t *testing.T) {
tests := []struct {
name string
input string
expected string
}{
{
name: "klog",
input: `I1018 15:20:42.861239 2386 logs_test.go:13] "Contextual Info Level 3" logger="foo" key="value"`,
expected: `I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value"`,
},
{
name: "json-with-nanoseconds",
input: `{"ts":1729270111728.125,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}`,
expected: `{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}`,
},
{
name: "json-might-not-have-nanoseconds",
input: `{"ts":1729270111728,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}`,
expected: `{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}`,
},
}
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
assert.Equal(t, test.expected, replaceWithStaticTimestamps(test.input))
require.Equal(t, test.expectStdout, testutil.ReplaceWithStaticTimestamps(stdoutStr), "stdout doesn't match")
require.Equal(t, test.expectStderr, testutil.ReplaceWithStaticTimestamps(stderrStr), "stderr doesn't match")
})
}
}
Expand Down
41 changes: 41 additions & 0 deletions pkg/testutil/logs.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,41 @@
package testutil

import (
"regexp"
)

// Replaces the klog and JSON timestamps with a static timestamp to make it
// easier to assert the logs. It also replaces the line number with 000 as it
// often changes.
//
// From: I1018 15:12:57.953433 22183 logs.go:000] log
// To: I0000 00:00:00.000000 00000 logs.go:000] log
//
// From: I1018 15:12:57.953433] log
// To: I0000 00:00:00.000000] log
//
// From: {"ts":1729258473588.828,"caller":"log/log.go:000","msg":"log Print","v":0}
// To: {"ts":0000000000000.000,"caller":"log/log.go:000","msg":"log Print","v":0}
//
// From: 2024/10/18 15:40:50 log Print
// To: 0000/00/00 00:00:00 log Print
func ReplaceWithStaticTimestamps(input string) string {
input = timestampRegexpKlog.ReplaceAllString(input, "0000 00:00:00.000000 00000")
input = timestampRegexpKlogAlt.ReplaceAllString(input, "0000 00:00:00.000000")
input = timestampRegexpJSON.ReplaceAllString(input, `"ts":0000000000000.000`)
input = timestampRegexpStdLog.ReplaceAllString(input, "0000/00/00 00:00:00")
input = fileAndLineRegexpJSON.ReplaceAllString(input, `"caller":"$1.go:000"`)
input = fileAndLineRegexpKlog.ReplaceAllString(input, " $1.go:000")
return input
}

var (
timestampRegexpStdLog = regexp.MustCompile(`\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}`)

timestampRegexpKlog = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6} +\d+`)
timestampRegexpKlogAlt = regexp.MustCompile(`\d{4} \d{2}:\d{2}:\d{2}\.\d{6}`)
fileAndLineRegexpKlog = regexp.MustCompile(` ([^:]+).go:\d+`)

timestampRegexpJSON = regexp.MustCompile(`"ts":\d+\.?\d*`)
fileAndLineRegexpJSON = regexp.MustCompile(`"caller":"([^"]+).go:\d+"`)
)
41 changes: 41 additions & 0 deletions pkg/testutil/logs_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,41 @@
package testutil

import (
"testing"

"github.com/stretchr/testify/assert"
)

func TestReplaceWithStaticTimestamps(t *testing.T) {
tests := []struct {
name string
input string
expected string
}{
{
name: "klog",
input: `I1018 15:20:42.861239 2386 logs_test.go:13] "Contextual Info Level 3" logger="foo" key="value"`,
expected: `I0000 00:00:00.000000 00000 logs_test.go:000] "Contextual Info Level 3" logger="foo" key="value"`,
},
{
name: "klog without process ID and without file name",
input: `E1114 11:15:39.455086] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="add"`,
expected: `E0000 00:00:00.000000] Cache update failure err="not a cacheResource type: *k8s.notCachable missing metadata/uid field" operation="add"`,
},
{
name: "json-with-nanoseconds",
input: `{"ts":1729270111728.125,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}`,
expected: `{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Warn","v":0}`,
},
{
name: "json-might-not-have-nanoseconds",
input: `{"ts":1729270111728,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}`,
expected: `{"ts":0000000000000.000,"caller":"logs/logs_test.go:000","msg":"slog Info","v":0}`,
},
}
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
assert.Equal(t, test.expected, ReplaceWithStaticTimestamps(test.input))
})
}
}