klog_test.go

Documentation: k8s.io/component-base/logs/json

     1  /*
     2  Copyright 2020 The Kubernetes Authors.
     3  
     4  Licensed under the Apache License, Version 2.0 (the "License");
     5  you may not use this file except in compliance with the License.
     6  You may obtain a copy of the License at
     7  
     8      http://www.apache.org/licenses/LICENSE-2.0
     9  
    10  Unless required by applicable law or agreed to in writing, software
    11  distributed under the License is distributed on an "AS IS" BASIS,
    12  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    13  See the License for the specific language governing permissions and
    14  limitations under the License.
    15  */
    16  
    17  package json
    18  
    19  import (
    20  	"bytes"
    21  	"errors"
    22  	"flag"
    23  	"fmt"
    24  	"strings"
    25  	"testing"
    26  	"time"
    27  
    28  	"github.com/stretchr/testify/assert"
    29  	"go.uber.org/zap/zapcore"
    30  
    31  	logsapi "k8s.io/component-base/logs/api/v1"
    32  	"k8s.io/klog/v2"
    33  )
    34  
    35  type kmeta struct {
    36  	Name, Namespace string
    37  }
    38  
    39  func (k kmeta) GetName() string {
    40  	return k.Name
    41  }
    42  
    43  func (k kmeta) GetNamespace() string {
    44  	return k.Namespace
    45  }
    46  
    47  var _ klog.KMetadata = kmeta{}
    48  
    49  func TestKlogIntegration(t *testing.T) {
    50  	timeNow = func() time.Time {
    51  		return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC)
    52  	}
    53  	fs := flag.FlagSet{}
    54  	klog.InitFlags(&fs)
    55  	err := fs.Set("v", "2")
    56  	if err != nil {
    57  		t.Fatalf("Failed to set verbosity")
    58  	}
    59  	tcs := []struct {
    60  		name   string
    61  		fun    func()
    62  		format string
    63  	}{
    64  		{
    65  			name: "Info",
    66  			fun: func() {
    67  				klog.Info("test ", 1)
    68  			},
    69  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
    70  		},
    71  		{
    72  			name: "V(1).Info",
    73  			fun: func() {
    74  				klog.V(1).Info("test ", 1)
    75  			},
    76  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":1}`,
    77  		},
    78  		{
    79  			name: "Infof",
    80  			fun: func() {
    81  				klog.Infof("test %d", 1)
    82  			},
    83  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
    84  		},
    85  		{
    86  			name: "V(1).Infof",
    87  			fun: func() {
    88  				klog.V(1).Infof("test %d", 1)
    89  			},
    90  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":1}`,
    91  		},
    92  		{
    93  			name: "Infoln",
    94  			fun: func() {
    95  				klog.Infoln("test", 1)
    96  			},
    97  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
    98  		},
    99  		{
   100  			name: "V(1).Infoln",
   101  			fun: func() {
   102  				klog.V(1).Infoln("test", 1)
   103  			},
   104  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":1}`,
   105  		},
   106  		{
   107  			name: "InfoDepth",
   108  			fun: func() {
   109  				klog.InfoDepth(1, "test ", 1)
   110  			},
   111  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
   112  		},
   113  		{
   114  			name: "InfoS",
   115  			fun: func() {
   116  				klog.InfoS("test", "count", 1)
   117  			},
   118  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":0,"count":1}`,
   119  		},
   120  		{
   121  			name: "V(1).InfoS",
   122  			fun: func() {
   123  				klog.V(1).InfoS("test", "count", 1)
   124  			},
   125  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":1,"count":1}`,
   126  		},
   127  		{
   128  			name: "V(2).InfoS",
   129  			fun: func() {
   130  				klog.V(2).InfoS("test", "count", 1)
   131  			},
   132  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":2,"count":1}`,
   133  		},
   134  		{
   135  			name: "V(3).InfoS",
   136  			fun: func() {
   137  				klog.V(3).InfoS("test", "count", 1)
   138  			},
   139  			// no output because of threshold 2
   140  		},
   141  		{
   142  			name: "InfoSDepth",
   143  			fun: func() {
   144  				klog.InfoSDepth(1, "test", "count", 1)
   145  			},
   146  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","v":0,"count":1}`,
   147  		},
   148  		{
   149  			name: "KObj",
   150  			fun: func() {
   151  				klog.InfoS("some", "pod", klog.KObj(&kmeta{Name: "pod-1", Namespace: "kube-system"}))
   152  			},
   153  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"some","v":0,"pod":{"name":"pod-1","namespace":"kube-system"}}`,
   154  		},
   155  		{
   156  			name: "KObjSlice",
   157  			fun: func() {
   158  				klog.InfoS("several", "pods",
   159  					klog.KObjSlice([]interface{}{
   160  						&kmeta{Name: "pod-1", Namespace: "kube-system"},
   161  						&kmeta{Name: "pod-2", Namespace: "kube-system"},
   162  					}))
   163  			},
   164  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"several","v":0,"pods":[{"name":"pod-1","namespace":"kube-system"},{"name":"pod-2","namespace":"kube-system"}]}`,
   165  		},
   166  		{
   167  			name: "Warning",
   168  			fun: func() {
   169  				klog.Warning("test ", 1)
   170  			},
   171  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
   172  		},
   173  		{
   174  			name: "WarningDepth",
   175  			fun: func() {
   176  				klog.WarningDepth(1, "test ", 1)
   177  			},
   178  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
   179  		},
   180  		{
   181  			name: "Warningln",
   182  			fun: func() {
   183  				klog.Warningln("test", 1)
   184  			},
   185  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
   186  		},
   187  		{
   188  			name: "Warningf",
   189  			fun: func() {
   190  				klog.Warningf("test %d", 1)
   191  			},
   192  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1","v":0}`,
   193  		},
   194  		{
   195  			name: "Error",
   196  			fun: func() {
   197  				klog.Error("test ", 1)
   198  			},
   199  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1"}`,
   200  		},
   201  		{
   202  			name: "ErrorDepth",
   203  			fun: func() {
   204  				klog.ErrorDepth(1, "test ", 1)
   205  			},
   206  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1"}`,
   207  		},
   208  		{
   209  			name: "Errorln",
   210  			fun: func() {
   211  				klog.Errorln("test", 1)
   212  			},
   213  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1"}`,
   214  		},
   215  		{
   216  			name: "Errorf",
   217  			fun: func() {
   218  				klog.Errorf("test %d", 1)
   219  			},
   220  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test 1"}`,
   221  		},
   222  		{
   223  			name: "ErrorS",
   224  			fun: func() {
   225  				err := errors.New("fail")
   226  				klog.ErrorS(err, "test", "count", 1)
   227  			},
   228  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","count":1,"err":"fail"}`,
   229  		},
   230  		{
   231  			name: "ErrorSDepth",
   232  			fun: func() {
   233  				err := errors.New("fail")
   234  				klog.ErrorSDepth(1, err, "test", "count", 1)
   235  			},
   236  			format: `{"ts":%f,"caller":"json/klog_test.go:%d","msg":"test","count":1,"err":"fail"}`,
   237  		},
   238  	}
   239  	for _, tc := range tcs {
   240  		t.Run(tc.name, func(t *testing.T) {
   241  			var buffer bytes.Buffer
   242  			writer := zapcore.AddSync(&buffer)
   243  			// This level is high enough to enable all log messages from this test.
   244  			verbosityLevel := logsapi.VerbosityLevel(100)
   245  			logger, _ := NewJSONLogger(verbosityLevel, writer, nil, nil)
   246  			klog.SetLogger(logger)
   247  			defer klog.ClearLogger()
   248  
   249  			tc.fun()
   250  			var ts float64
   251  			var lineNo int
   252  			logString := strings.TrimSuffix(buffer.String(), "\n")
   253  			if tc.format == "" {
   254  				if logString != "" {
   255  					t.Fatalf("expected no output, got: %s", logString)
   256  				}
   257  				return
   258  			}
   259  			n, err := fmt.Sscanf(logString, tc.format, &ts, &lineNo)
   260  			if n != 2 || err != nil {
   261  				t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logString)
   262  			}
   263  			expect := fmt.Sprintf(tc.format, ts, lineNo)
   264  			if !assert.Equal(t, expect, logString) {
   265  				t.Errorf("Info has wrong format \n expect:%s\n got:%s", expect, logString)
   266  			}
   267  
   268  		})
   269  	}
   270  }
   271  
   272  // TestKlogV test klog -v(--verbose) func available with json logger
   273  func TestKlogV(t *testing.T) {
   274  	var buffer testBuff
   275  	writer := zapcore.AddSync(&buffer)
   276  	logger, _ := NewJSONLogger(100, writer, nil, nil)
   277  	klog.SetLogger(logger)
   278  	defer klog.ClearLogger()
   279  	fs := flag.FlagSet{}
   280  	klog.InitFlags(&fs)
   281  	totalLogsWritten := 0
   282  
   283  	defer func() {
   284  		err := fs.Set("v", "0")
   285  		if err != nil {
   286  			t.Fatalf("Failed to reset verbosity to 0")
   287  		}
   288  	}()
   289  
   290  	for i := 0; i < 11; i++ {
   291  		err := fs.Set("v", fmt.Sprintf("%d", i))
   292  		if err != nil {
   293  			t.Fatalf("Failed to set verbosity")
   294  		}
   295  		for j := 0; j < 11; j++ {
   296  			klog.V(klog.Level(j)).Info("test", "time", time.Microsecond)
   297  			logWritten := buffer.writeCount > 0
   298  			totalLogsWritten += buffer.writeCount
   299  			buffer.writeCount = 0
   300  			if logWritten == (i < j) {
   301  				t.Errorf("klog.V(%d).Info(...) wrote log when -v=%d", j, i)
   302  			}
   303  		}
   304  	}
   305  	if totalLogsWritten != 66 {
   306  		t.Fatalf("Unexpected number of logs written, got %d, expected 66", totalLogsWritten)
   307  	}
   308  }
   309
View as plain text