From 8fd55a1d813cd5f5cd80cd6004336c118a85a0ef Mon Sep 17 00:00:00 2001 From: Joshua Casey Date: Wed, 30 Aug 2023 16:52:23 -0500 Subject: [PATCH] Adjust test expectations for compilation differences with 1.21 - Requires some production code changes, to use pointers to function variables instead of pointers to functions --- .../active_directory_upstream_watcher.go | 9 ++- internal/plog/config_test.go | 59 +++++++++++-------- internal/plog/plog_test.go | 54 +++++++++-------- internal/upstreamldap/upstreamldap.go | 3 +- 4 files changed, 71 insertions(+), 54 deletions(-) diff --git a/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go b/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go index 9cb773b5..150c903a 100644 --- a/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go +++ b/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go @@ -387,7 +387,8 @@ func (c *activeDirectoryWatcherController) updateStatus(ctx context.Context, ups } } -func microsoftUUIDFromBinaryAttr(attributeName string) func(entry *ldap.Entry) (string, error) { +//nolint:gochecknoglobals // this needs to be a global variable so that tests can check pointer equality +var microsoftUUIDFromBinaryAttr = func(attributeName string) func(*ldap.Entry) (string, error) { // validation has already been done so we can just get the attribute... return func(entry *ldap.Entry) (string, error) { binaryUUID := entry.GetRawAttributeValue(attributeName) @@ -442,7 +443,8 @@ func getDomainFromDistinguishedName(distinguishedName string) (string, error) { return strings.Join(domainComponents[1:], "."), nil } -func validUserAccountControl(entry *ldap.Entry, _ provider.RefreshAttributes) error { +//nolint:gochecknoglobals // this needs to be a global variable so that tests can check pointer equality +var validUserAccountControl = func(entry *ldap.Entry, _ provider.RefreshAttributes) error { userAccountControl, err := strconv.Atoi(entry.GetAttributeValue(userAccountControlAttribute)) if err != nil { return err @@ -455,7 +457,8 @@ func validUserAccountControl(entry *ldap.Entry, _ provider.RefreshAttributes) er return nil } -func validComputedUserAccountControl(entry *ldap.Entry, _ provider.RefreshAttributes) error { +//nolint:gochecknoglobals // this needs to be a global variable so that tests can check pointer equality +var validComputedUserAccountControl = func(entry *ldap.Entry, _ provider.RefreshAttributes) error { userAccountControl, err := strconv.Atoi(entry.GetAttributeValue(userAccountControlComputedAttribute)) if err != nil { return err diff --git a/internal/plog/config_test.go b/internal/plog/config_test.go index a3e7425e..4645cb62 100644 --- a/internal/plog/config_test.go +++ b/internal/plog/config_test.go @@ -11,7 +11,6 @@ import ( "os" "runtime" "strconv" - "strings" "testing" "time" @@ -44,8 +43,6 @@ func TestFormat(t *testing.T) { wd, err := os.Getwd() require.NoError(t, err) - const startLogLine = 47 // make this match the current line number - Info("hello", "happy", "day", "duration", time.Hour+time.Minute) require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) @@ -57,7 +54,7 @@ func TestFormat(t *testing.T) { "message": "hello", "happy": "day", "duration": "1h1m0s" -}`, wd, startLogLine+2), scanner.Text()) +}`, wd, getLineNumberOfCaller()-11), scanner.Text()) Logr().WithName("burrito").Error(errInvalidLogLevel, "wee", "a", "b") require.True(t, scanner.Scan()) @@ -71,7 +68,7 @@ func TestFormat(t *testing.T) { "a": "b", "error": "invalid log level, valid choices are the empty string, info, debug, trace and all", "logger": "burrito" -}`, wd, startLogLine+2+13), scanner.Text()) +}`, wd, getLineNumberOfCaller()-12), scanner.Text()) Logr().V(klogLevelWarning).Info("hey") // note that this fails to set the custom warning key because it is not via plog require.True(t, scanner.Scan()) @@ -82,7 +79,7 @@ func TestFormat(t *testing.T) { "timestamp": "2022-11-21T23:37:26.953313Z", "caller": "%s/config_test.go:%d$plog.TestFormat", "message": "hey" -}`, wd, startLogLine+2+13+14), scanner.Text()) +}`, wd, getLineNumberOfCaller()-9), scanner.Text()) Warning("bad stuff") // note that this sets the custom warning key because it is via plog require.True(t, scanner.Scan()) @@ -94,7 +91,7 @@ func TestFormat(t *testing.T) { "caller": "%s/config_test.go:%d$plog.TestFormat", "message": "bad stuff", "warning": true -}`, wd, startLogLine+2+13+14+11), scanner.Text()) +}`, wd, getLineNumberOfCaller()-10), scanner.Text()) func() { DebugErr("something happened", errInvalidLogFormat, "an", "item") }() require.True(t, scanner.Scan()) @@ -107,7 +104,7 @@ func TestFormat(t *testing.T) { "message": "something happened", "error": "invalid log format, valid choices are the empty string, json and text", "an": "item" -}`, wd, startLogLine+2+13+14+11+12), scanner.Text()) +}`, wd, getLineNumberOfCaller()-11), scanner.Text()) Trace("should not be logged", "for", "sure") require.Empty(t, buf.String()) @@ -124,11 +121,6 @@ func TestFormat(t *testing.T) { require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) - line := "1576" - if strings.Contains(runtime.Version(), "1.19") { - line = "1446" - } - require.JSONEq(t, fmt.Sprintf(` { "level": "info", @@ -137,14 +129,14 @@ func TestFormat(t *testing.T) { "message": "has a stack trace!", "logger": "stacky.does", "stacktrace": %s -}`, wd, startLogLine+2+13+14+11+12+24, +}`, wd, getLineNumberOfCaller()-12, strconv.Quote( fmt.Sprintf( `go.pinniped.dev/internal/plog.TestFormat %s/config_test.go:%d testing.tRunner - %s/src/testing/testing.go:%s`, - wd, startLogLine+2+13+14+11+12+24, runtime.GOROOT(), line, + %s/src/testing/testing.go:%d`, + wd, getLineNumberOfCaller()-19, runtime.GOROOT(), getLineNumberOfCaller(2), ), ), ), scanner.Text()) @@ -158,13 +150,13 @@ testing.tRunner require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(nowStr+` plog/config_test.go:%d something happened {"error": "invalid log format, valid choices are the empty string, json and text", "an": "item"}`, - startLogLine+2+13+14+11+12+24+28+6), scanner.Text()) + getLineNumberOfCaller()-4), scanner.Text()) Logr().WithName("burrito").Error(errInvalidLogLevel, "wee", "a", "b", "slightly less than a year", 363*24*time.Hour, "slightly more than 2 years", 2*367*24*time.Hour) require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(nowStr+` burrito plog/config_test.go:%d wee {"a": "b", "slightly less than a year": "363d", "slightly more than 2 years": "2y4d", "error": "invalid log level, valid choices are the empty string, info, debug, trace and all"}`, - startLogLine+2+13+14+11+12+24+28+6+6), scanner.Text()) + getLineNumberOfCaller()-4), scanner.Text()) origTimeNow := textlogger.TimeNow t.Cleanup(func() { @@ -190,19 +182,19 @@ testing.tRunner require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "what is happening" does klog="work?"`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6), scanner.Text()) + pid, getLineNumberOfCaller()-4), scanner.Text()) Logr().WithName("panda").V(KlogLevelDebug).Info("are the best", "yes?", "yes.") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "panda: are the best" yes?="yes."`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6), scanner.Text()) + pid, getLineNumberOfCaller()-4), scanner.Text()) New().WithName("hi").WithName("there").WithValues("a", 1, "b", 2).Always("do it") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "hi/there: do it" a=1 b=2`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+6), scanner.Text()) + pid, getLineNumberOfCaller()-4), scanner.Text()) l := WithValues("x", 33, "z", 22) l.Debug("what to do") @@ -210,17 +202,17 @@ testing.tRunner require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "what to do" x=33 z=22`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+6), scanner.Text()) + pid, getLineNumberOfCaller()-5), scanner.Text()) require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "and why" x=33 z=22`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+6), scanner.Text()) + pid, getLineNumberOfCaller()-8), scanner.Text()) old.Always("should be klog text format", "for", "sure") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change: should be klog text format" is="old" for="sure"`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+6), scanner.Text()) + pid, getLineNumberOfCaller()-4), scanner.Text()) // make sure child loggers do not share state old1 := old.WithValues("i am", "old1") @@ -230,11 +222,11 @@ testing.tRunner require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change: warn" is="old" i am="old1" warning=true`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+9+6), scanner.Text()) + pid, getLineNumberOfCaller()-5), scanner.Text()) require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change/old2: info" is="old"`, - pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+9+1+6), scanner.Text()) + pid, getLineNumberOfCaller()-8), scanner.Text()) Trace("should not be logged", "for", "sure") require.Empty(t, buf.String()) @@ -364,3 +356,18 @@ func getKlogLevel() klog.Level { return -1 } + +// getLineNumberOfCaller returns the line number of the source code that invoked this function. +// If maybeSkip is provided, returns the line number from a different point in the call stack. +// This is useful to test log output that prints a call stack with line numbers. +func getLineNumberOfCaller(maybeSkip ...int) int { + skip := 1 + if len(maybeSkip) > 0 { + skip = maybeSkip[0] + } + + if _, _, line, ok := runtime.Caller(skip); ok { + return line + } + return -1 +} diff --git a/internal/plog/plog_test.go b/internal/plog/plog_test.go index c873747e..c0d1007f 100644 --- a/internal/plog/plog_test.go +++ b/internal/plog/plog_test.go @@ -6,6 +6,7 @@ package plog import ( "bytes" "fmt" + "runtime" "strings" "testing" "time" @@ -156,17 +157,17 @@ func TestPlog(t *testing.T) { testAllPlogMethods(l.withDepth(2)) }, want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"always","panda":2} +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"always","panda":2} `, }, { @@ -284,19 +285,24 @@ func TestPlog(t *testing.T) { }() }() }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"always","panda":2} -`, + want: fmt.Sprintf(` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"always","panda":2} +`, func() string { + if strings.Contains(runtime.Version(), "1.21") { + return "func13.TestPlog.func13.1.func2" + } + return "func13.1.1" + }()), }, { name: "closure depth -1", diff --git a/internal/upstreamldap/upstreamldap.go b/internal/upstreamldap/upstreamldap.go index bbf645c1..6488cca1 100644 --- a/internal/upstreamldap/upstreamldap.go +++ b/internal/upstreamldap/upstreamldap.go @@ -871,7 +871,8 @@ func (p *Provider) traceRefreshFailure(t *trace.Trace, err error) { ) } -func AttributeUnchangedSinceLogin(attribute string) func(*ldap.Entry, provider.RefreshAttributes) error { +//nolint:gochecknoglobals // this needs to be a global variable so that tests can check pointer equality +var AttributeUnchangedSinceLogin = func(attribute string) func(*ldap.Entry, provider.RefreshAttributes) error { return func(entry *ldap.Entry, storedAttributes provider.RefreshAttributes) error { prevAttributeValue := storedAttributes.AdditionalAttributes[attribute] newValues := entry.GetRawAttributeValues(attribute)