Repository: kubernetes/klog (go)

Issue:
Structured logging behaviour changed from v2.0.0 to v2.1.0
/kind bug

Structured logging using levelled V function changed.

**What steps did you take and what happened:**
Create test program
`$ go mod init klogtest`
```golang
package main

import (
	"k8s.io/klog/v2"
)

func main() {
	klog.InitFlags(nil)
	klog.InfoS("Hello1", "msg", "without V")
	klog.V(0).InfoS("Hello2", "msg", "message with V(0)")
}
```

Output:
```
$ grep klog go.mod 
	k8s.io/klog/v2 v2.1.0
$ go run .
I0614 15:19:37.239517  118778 main.go:9] "Hello1" msg="without V"
I0614 15:19:37.239593  118778 main.go:10] "Hello2" [msg message with V(0)]="(MISSING)"
```

**What did you expect to happen:**
Change the version back to v2.0.0 in the `go.mod` file and run again:
```
$ grep klog go.mod 
	k8s.io/klog/v2 v2.0.0
$ go run .
I0614 15:19:45.638733  118902 main.go:9] "Hello1" msg="without V"
I0614 15:19:45.638838  118902 main.go:10] "Hello2" msg="message with V(0)"
```




Pull request:
Fix missing fields in verbose InfoS
Fixes #165

The recent update to v2.1.0 highlighted the omission of `...` in Verbose.InfoS when calling loggingT.infoS.

This complies because the final parameter for loggingT.infoS, accepts `...interface{}` and that interface just thinks all the key value pairs forms a single array. This produces output like `[key value]=(missing)` instead of `key="value"`

Patch:
diff --git a/klog.go b/klog.go
index b0091f4..ae2b861 100644
--- a/klog.go
+++ b/klog.go
@@ -1320,7 +1320,7 @@ func (v Verbose) Infof(format string, args ...interface{}) {
 // See the documentation of V for usage.
 func (v Verbose) InfoS(msg string, keysAndValues ...interface{}) {
 	if v.enabled {
-		logging.infoS(v.logr, msg, keysAndValues)
+		logging.infoS(v.logr, msg, keysAndValues...)
 	}
 }
 


Test patch:
diff --git a/klog_test.go b/klog_test.go
index f46ba91..ff95814 100644
--- a/klog_test.go
+++ b/klog_test.go
@@ -820,6 +820,64 @@ func TestInfoS(t *testing.T) {
 	}
 }
 
+// Test that Verbose.InfoS works as advertised.
+func TestVInfoS(t *testing.T) {
+	setFlags()
+	defer logging.swap(logging.newBuffers())
+	timeNow = func() time.Time {
+		return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
+	}
+	pid = 1234
+	var testDataInfo = []struct {
+		msg        string
+		format     string
+		keysValues []interface{}
+	}{
+		{
+			msg:        "test",
+			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n",
+			keysValues: []interface{}{"pod", "kubedns"},
+		},
+		{
+			msg:        "test",
+			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" replicaNum=20\n",
+			keysValues: []interface{}{"replicaNum", 20},
+		},
+		{
+			msg:        "test",
+			format:     "I0102 15:04:05.067890    1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
+			keysValues: []interface{}{"err", errors.New("test error")},
+		},
+	}
+
+	logging.verbosity.Set("2")
+	defer logging.verbosity.Set("0")
+
+	for l := Level(0); l < Level(4); l++ {
+		for _, data := range testDataInfo {
+			logging.file[infoLog] = &flushBuffer{}
+
+			V(l).InfoS(data.msg, data.keysValues...)
+
+			var want string
+			var line int
+			if l <= 2 {
+				n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
+				if n != 1 || err != nil {
+					t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
+				}
+
+				want = fmt.Sprintf(data.format, line)
+			} else {
+				want = ""
+			}
+			if contents(infoLog) != want {
+				t.Errorf("V(%d).InfoS has unexpected output: \n got:\t%s\nwant:\t%s", l, contents(infoLog), want)
+			}
+		}
+	}
+}
+
 // Test that ErrorS works as advertised.
 func TestErrorS(t *testing.T) {
 	setFlags()