log: simplify API (istio#795)

Remove callerSkip from RegisterScope; it should always be 0. Remove ability to pass multiple values to non `f` types (log.Info). This removes a number of bugs in usage, as calls need to be very careful about spacing. Most callers should use structured logs. This simplicity will make moving to istio/istio#44683 easier as well.
miaoyq · May 2, 2023 · 41a8a76 · 41a8a76
1 parent 0287eb5
commit 41a8a76
Show file tree

Hide file tree

Showing 8 changed files with 47 additions and 94 deletions.
diff --git a/log/config.go b/log/config.go
@@ -300,7 +300,7 @@ func processLevels(allScopes map[string]*Scope, arg string, setter func(*Scope,
 			}
 			return nil
 		} else if s == GrpcScopeName {
-			grpcScope := RegisterScope(GrpcScopeName, "", 3)
+			grpcScope := registerScope(GrpcScopeName, "", 3)
 			logGrpc = true
 			setter(grpcScope, l)
 			return nil

diff --git a/log/config_test.go b/log/config_test.go
@@ -91,7 +91,7 @@ func TestTimestampProperMicros(t *testing.T) {
 
 func TestOverrides(t *testing.T) {
 	resetGlobals()
-	s := RegisterScope("TestOverrides", "For testing", 0)
+	s := RegisterScope("TestOverrides", "For testing")
 
 	o := DefaultOptions()
 	o.outputLevels = "default:debug,all:info"

diff --git a/log/default.go b/log/default.go
@@ -17,7 +17,7 @@ package log
 // These functions enable logging using a global Scope. See scope.go for usage information.
 
 func registerDefaultScope() *Scope {
-	return RegisterScope(DefaultScopeName, "Unscoped logging messages.", 1)
+	return registerScope(DefaultScopeName, "Unscoped logging messages.", 1)
 }
 
 var defaultScope = registerDefaultScope()
@@ -38,8 +38,8 @@ func FatalEnabled() bool {
 }
 
 // Error outputs a message at error level.
-func Error(fields ...any) {
-	defaultScope.Error(fields...)
+func Error(fields any) {
+	defaultScope.Error(fields)
 }
 
 // Errorf uses fmt.Sprintf to construct and log a message at error level.
@@ -53,13 +53,8 @@ func ErrorEnabled() bool {
 }
 
 // Warn outputs a message at warn level.
-func Warn(fields ...any) {
-	defaultScope.Warn(fields...)
-}
-
-// Warna uses fmt.Sprint to construct and log a message at warn level.
-func Warna(args ...any) {
-	defaultScope.Warna(args...)
+func Warn(fields any) {
+	defaultScope.Warn(fields)
 }
 
 // Warnf uses fmt.Sprintf to construct and log a message at warn level.
@@ -73,8 +68,8 @@ func WarnEnabled() bool {
 }
 
 // Info outputs a message at info level.
-func Info(fields ...any) {
-	defaultScope.Info(fields...)
+func Info(fields any) {
+	defaultScope.Info(fields)
 }
 
 // Infof uses fmt.Sprintf to construct and log a message at info level.
@@ -88,8 +83,8 @@ func InfoEnabled() bool {
 }
 
 // Debug outputs a message at debug level.
-func Debug(fields ...any) {
-	defaultScope.Debug(fields...)
+func Debug(fields any) {
+	defaultScope.Debug(fields)
 }
 
 // Debugf uses fmt.Sprintf to construct and log a message at debug level.

diff --git a/log/default_test.go b/log/default_test.go
@@ -72,10 +72,6 @@ func TestDefault(t *testing.T) {
 			f:   func() { Warnf("%s", "Hello") },
 			pat: timePattern + "\twarn\tHello",
 		},
-		{
-			f:   func() { Warna("Hello") },
-			pat: timePattern + "\twarn\tHello",
-		},
 
 		{
 			f:   func() { Error("Hello") },
@@ -211,7 +207,7 @@ func TestErrorDictionary(t *testing.T) {
 			t.Errorf("Got err '%v', expecting success", err)
 		}
 
-		Info(ie, "Hello")
+		Infof(ie, "Hello")
 		_ = Sync()
 	})
 	if err != nil {

diff --git a/log/klog.go b/log/klog.go
@@ -24,7 +24,7 @@ import (
 )
 
 var (
-	KlogScope     = RegisterScope("klog", "", 0)
+	KlogScope     = RegisterScope("klog", "")
 	configureKlog = sync.Once{}
 )
 

diff --git a/log/options_test.go b/log/options_test.go
@@ -272,14 +272,14 @@ func TestOpts(t *testing.T) {
 			})
 		}
 
-		_ = RegisterScope("foo", "bar", 0)
+		_ = RegisterScope("foo", "bar")
 	}
 }
 
 func TestSetLevel(t *testing.T) {
 	resetGlobals()
 
-	_ = RegisterScope("TestSetLevel", "", 0)
+	_ = RegisterScope("TestSetLevel", "")
 
 	cases := []struct {
 		levels      string

diff --git a/log/scope.go b/log/scope.go
@@ -90,7 +90,12 @@ func registerDefaultHandler(callback scopeHandlerCallbackFunc) {
 // for a single process, the same Scope struct is returned.
 //
 // Scope names cannot include colons, commas, or periods.
-func RegisterScope(name string, description string, callerSkip int) *Scope {
+func RegisterScope(name string, description string) *Scope {
+	// We only allow internal callers to set callerSkip
+	return registerScope(name, description, 0)
+}
+
+func registerScope(name string, description string, callerSkip int) *Scope {
 	if strings.ContainsAny(name, ":,.") {
 		panic(fmt.Sprintf("scope name %s is invalid, it cannot contain colons, commas, or periods", name))
 	}
@@ -173,14 +178,9 @@ func (s *Scope) FatalEnabled() bool {
 }
 
 // Error outputs a message at error level.
-func (s *Scope) Error(args ...any) {
+func (s *Scope) Error(args any) {
 	if s.GetOutputLevel() >= ErrorLevel {
-		ie, firstIdx := getErrorStruct(args)
-		if firstIdx == 0 {
-			s.callHandlers(ErrorLevel, s, ie, fmt.Sprint(args...))
-			return
-		}
-		s.callHandlers(ErrorLevel, s, ie, fmt.Sprint(args[firstIdx:]...))
+		s.callHandlers(ErrorLevel, s, nil, fmt.Sprint(args))
 	}
 }
 
@@ -202,23 +202,12 @@ func (s *Scope) ErrorEnabled() bool {
 }
 
 // Warn outputs a message at warn level.
-func (s *Scope) Warn(args ...any) {
+func (s *Scope) Warn(args any) {
 	if s.GetOutputLevel() >= WarnLevel {
-		ie, firstIdx := getErrorStruct(args)
-		if firstIdx == 0 {
-			s.callHandlers(WarnLevel, s, ie, fmt.Sprint(args...))
-			return
-		}
-		s.callHandlers(WarnLevel, s, ie, fmt.Sprint(args[firstIdx:]...))
+		s.callHandlers(WarnLevel, s, nil, fmt.Sprint(args))
 	}
 }
 
-// Warna uses fmt.Sprint to construct and log a message at warn level.
-// Deprecated: use Warn.
-func (s *Scope) Warna(args ...any) {
-	s.Warn(args...)
-}
-
 // Warnf uses fmt.Sprintf to construct and log a message at warn level.
 func (s *Scope) Warnf(args ...any) {
 	if s.GetOutputLevel() >= WarnLevel {
@@ -237,14 +226,9 @@ func (s *Scope) WarnEnabled() bool {
 }
 
 // Info outputs a message at info level.
-func (s *Scope) Info(args ...any) {
+func (s *Scope) Info(args any) {
 	if s.GetOutputLevel() >= InfoLevel {
-		ie, firstIdx := getErrorStruct(args)
-		if firstIdx == 0 {
-			s.callHandlers(InfoLevel, s, ie, fmt.Sprint(args...))
-			return
-		}
-		s.callHandlers(InfoLevel, s, ie, fmt.Sprint(args[firstIdx:]...))
+		s.callHandlers(InfoLevel, s, nil, fmt.Sprint(args))
 	}
 }
 
@@ -266,14 +250,9 @@ func (s *Scope) InfoEnabled() bool {
 }
 
 // Debug outputs a message at debug level.
-func (s *Scope) Debug(args ...any) {
+func (s *Scope) Debug(args any) {
 	if s.GetOutputLevel() >= DebugLevel {
-		ie, firstIdx := getErrorStruct(args)
-		if firstIdx == 0 {
-			s.callHandlers(DebugLevel, s, ie, fmt.Sprint(args...))
-			return
-		}
-		s.callHandlers(DebugLevel, s, ie, fmt.Sprint(args[firstIdx:]...))
+		s.callHandlers(DebugLevel, s, nil, fmt.Sprint(args))
 	}
 }
 

diff --git a/log/scope_test.go b/log/scope_test.go
@@ -91,7 +91,7 @@ func TestKlog(t *testing.T) {
 }
 
 func TestBasicScopes(t *testing.T) {
-	s := RegisterScope("testScope", "z", 0)
+	s := RegisterScope("testScope", "z")
 
 	cases := []struct {
 		f          func()
@@ -102,13 +102,8 @@ func TestBasicScopes(t *testing.T) {
 		stackLevel Level
 	}{
 		{
-			// zap.Field is no longer supported, prints like regular Sprint.
-			f:   func() { s.Debug("Hello", zap.String("key", "value"), zap.Int("intkey", 123)) },
-			pat: timePattern + "\tdebug\ttestScope\tHello{key 15 0 value <nil>} {intkey 11 123  <nil>}",
-		},
-		{
-			f:   func() { s.Debug("Hello", " some", " fields") },
-			pat: timePattern + "\tdebug\ttestScope\tHello some fields",
+			f:   func() { s.Debug("Hello") },
+			pat: timePattern + "\tdebug\ttestScope\tHello",
 		},
 		{
 			f:   func() { s.Debugf("Hello") },
@@ -120,12 +115,8 @@ func TestBasicScopes(t *testing.T) {
 		},
 
 		{
-			f:   func() { s.Info("Hello", zap.String("key", "value"), zap.Int("intkey", 123)) },
-			pat: timePattern + "\tinfo\ttestScope\tHello{key 15 0 value <nil>} {intkey 11 123  <nil>}",
-		},
-		{
-			f:   func() { s.Info("Hello", " some", " fields") },
-			pat: timePattern + "\tinfo\ttestScope\tHello some fields",
+			f:   func() { s.Info("Hello") },
+			pat: timePattern + "\tinfo\ttestScope\tHello",
 		},
 		{
 			f:   func() { s.Infof("Hello") },
@@ -137,12 +128,8 @@ func TestBasicScopes(t *testing.T) {
 		},
 
 		{
-			f:   func() { s.Warn("Hello", zap.String("key", "value"), zap.Int("intkey", 123)) },
-			pat: timePattern + "\twarn\ttestScope\tHello{key 15 0 value <nil>} {intkey 11 123  <nil>}",
-		},
-		{
-			f:   func() { s.Warn("Hello", " some", " fields") },
-			pat: timePattern + "\twarn\ttestScope\tHello some fields",
+			f:   func() { s.Warn("Hello") },
+			pat: timePattern + "\twarn\ttestScope\tHello",
 		},
 		{
 			f:   func() { s.Warnf("Hello") },
@@ -152,14 +139,10 @@ func TestBasicScopes(t *testing.T) {
 			f:   func() { s.Warnf("%s", "Hello") },
 			pat: timePattern + "\twarn\ttestScope\tHello",
 		},
-		{
-			f:   func() { s.Warna("Hello") },
-			pat: timePattern + "\twarn\ttestScope\tHello",
-		},
 
 		{
-			f:   func() { s.Error("Hello", zap.String("key", "value"), zap.Int("intkey", 123)) },
-			pat: timePattern + "\terror\ttestScope\tHello{key 15 0 value <nil>} {intkey 11 123  <nil>}",
+			f:   func() { s.Error("Hello") },
+			pat: timePattern + "\terror\ttestScope\tHello",
 		},
 		{
 			f:   func() { s.Errorf("Hello") },
@@ -294,7 +277,7 @@ func TestBasicScopes(t *testing.T) {
 func TestScopeWithLabel(t *testing.T) {
 	const name = "TestScope"
 	const desc = "Desc"
-	s := RegisterScope(name, desc, 0)
+	s := RegisterScope(name, desc)
 	s.SetOutputLevel(DebugLevel)
 
 	lines, err := captureStdout(func() {
@@ -318,7 +301,7 @@ func TestScopeWithLabel(t *testing.T) {
 func TestScopeJSON(t *testing.T) {
 	const name = "TestScope"
 	const desc = "Desc"
-	s := RegisterScope(name, desc, 0)
+	s := RegisterScope(name, desc)
 	s.SetOutputLevel(DebugLevel)
 
 	lines, err := captureStdout(func() {
@@ -340,7 +323,7 @@ func TestScopeJSON(t *testing.T) {
 func TestScopeErrorDictionary(t *testing.T) {
 	const name = "TestScope"
 	const desc = "Desc"
-	s := RegisterScope(name, desc, 0)
+	s := RegisterScope(name, desc)
 	s.SetOutputLevel(DebugLevel)
 
 	ie := &structured.Error{
@@ -371,7 +354,7 @@ func TestScopeErrorDictionary(t *testing.T) {
 func TestScopeErrorDictionaryWrap(t *testing.T) {
 	const name = "TestScope"
 	const desc = "Desc"
-	s := RegisterScope(name, desc, 0)
+	s := RegisterScope(name, desc)
 	s.SetOutputLevel(DebugLevel)
 
 	lines, err := captureStdout(func() {
@@ -422,7 +405,7 @@ func mustRegexMatchString(t *testing.T, got, want string) {
 func TestScopeEnabled(t *testing.T) {
 	const name = "TestEnabled"
 	const desc = "Desc"
-	s := RegisterScope(name, desc, 0)
+	s := RegisterScope(name, desc)
 
 	if n := s.Name(); n != name {
 		t.Errorf("Got %s, expected %s", n, name)
@@ -480,8 +463,8 @@ func TestScopeEnabled(t *testing.T) {
 }
 
 func TestMultipleScopesWithSameName(t *testing.T) {
-	z1 := RegisterScope("zzzz", "z", 0)
-	z2 := RegisterScope("zzzz", "z", 0)
+	z1 := RegisterScope("zzzz", "z")
+	z2 := RegisterScope("zzzz", "z")
 
 	if z1 != z2 {
 		t.Error("Expecting the same scope objects, got different ones")
@@ -493,7 +476,7 @@ func TestFind(t *testing.T) {
 		t.Error("Found scope, but expected it wouldn't exist")
 	}
 
-	_ = RegisterScope("TestFind", "", 0)
+	_ = RegisterScope("TestFind", "")
 
 	if z := FindScope("TestFind"); z == nil {
 		t.Error("Did not find scope, expected to find it")
@@ -528,7 +511,7 @@ func tryBadName(t *testing.T, name string) {
 		t.Errorf("Expecting to panic when using bad scope name %s, but didn't", name)
 	}()
 
-	_ = RegisterScope(name, "A poorly named scope", 0)
+	_ = RegisterScope(name, "A poorly named scope")
 }
 
 func TestBadWriter(t *testing.T) {
-Original file line number
+Diff line change
@@ Expand Up / @@ -24,7 +24,7 @@ import ( @@
     )
     var (
-    	KlogScope     = RegisterScope("klog", "", 0)
+    	KlogScope     = RegisterScope("klog", "")
     	configureKlog = sync.Once{}
     )
@@ Expand Down @@