log_test.go

Documentation: kubevirt.io/client-go/log

     1  /*
     2   * This file is part of the KubeVirt project
     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   * Copyright 2017 Red Hat, Inc.
    17   *
    18   */
    19  
    20  package log
    21  
    22  import (
    23  	"errors"
    24  	"fmt"
    25  	"path/filepath"
    26  	"runtime"
    27  	"strings"
    28  	"testing"
    29  
    30  	v12 "k8s.io/apimachinery/pkg/apis/meta/v1"
    31  
    32  	v1 "kubevirt.io/api/core/v1"
    33  )
    34  
    35  var logCalled bool = false
    36  var logParams []interface{} = make([]interface{}, 0)
    37  
    38  type MockLogger struct {
    39  }
    40  
    41  func (l MockLogger) Log(params ...interface{}) error {
    42  	logCalled = true
    43  	logParams = append(logParams, params)
    44  	return nil
    45  }
    46  
    47  func assert(t *testing.T, condition bool, failMessage string) {
    48  	if !condition {
    49  		_, filePath, lineNumber, _ := runtime.Caller(1)
    50  		fileName := filepath.Base(filePath)
    51  		t.Fatalf("[%s:%d] %s", fileName, lineNumber, failMessage)
    52  	}
    53  }
    54  
    55  func setUp() {
    56  	defaultComponent = "test"
    57  	logCalled = false
    58  	logParams = make([]interface{}, 0)
    59  }
    60  
    61  func tearDown() {
    62  
    63  }
    64  
    65  func TestDefaultLogLevels(t *testing.T) {
    66  	setUp()
    67  	log := MakeLogger(MockLogger{})
    68  	log.Log("default level message")
    69  	assert(t, logCalled, "default loglevel should have been info")
    70  	tearDown()
    71  }
    72  
    73  // Simply a self-check test as most tests will depend on this behavior working
    74  // Enforces that unit tests are run in isolated contexts
    75  func TestMockLogger(t *testing.T) {
    76  	setUp()
    77  	l := MockLogger{}
    78  	assert(t, !logCalled, "Test Case was not correctly initialized")
    79  	assert(t, len(logParams) == 0, "logParams was not reset")
    80  	l.Log("test", "message")
    81  	assert(t, logCalled, "MockLogger was not called")
    82  	tearDown()
    83  }
    84  
    85  func TestBadLevel(t *testing.T) {
    86  	setUp()
    87  	l := Logger("test")
    88  	error := l.SetLogLevel(10)
    89  	assert(t, error != nil, "Allowed to set illegal log level")
    90  	assert(t, l.filterLevel != 10, "Allowed to set illegal log level")
    91  	tearDown()
    92  }
    93  
    94  func TestGoodLevel(t *testing.T) {
    95  	setUp()
    96  	l := Logger("test")
    97  	error := l.SetLogLevel(INFO)
    98  	assert(t, error == nil, "Unable to set log level")
    99  	tearDown()
   100  }
   101  
   102  func TestComponent(t *testing.T) {
   103  	setUp()
   104  	log := MakeLogger(MockLogger{})
   105  	log.Log("foo", "bar")
   106  
   107  	assert(t, len(logParams) == 1, "Expected 1 log line")
   108  
   109  	logEntry := logParams[0].([]interface{})
   110  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   111  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   112  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   113  	tearDown()
   114  }
   115  
   116  func TestWith(t *testing.T) {
   117  	setUp()
   118  	log := MakeLogger(MockLogger{})
   119  
   120  	log.With("arg1", "val1").Log("foo1", "bar1")
   121  	log.With("arg2", "val2").Log("foo2", "bar2")
   122  
   123  	assert(t, len(logParams) == 2, "Expected 2 log lines")
   124  
   125  	logEntry := logParams[0].([]interface{})
   126  	assert(t, logEntry[8].(string) == "arg1", "Custom With() field was not logged")
   127  	assert(t, logEntry[9].(string) == "val1", "Custom With() field was not logged")
   128  
   129  	logEntry = logParams[1].([]interface{})
   130  	assert(t, logEntry[8].(string) == "arg2", "Custom With() was not logged")
   131  	assert(t, logEntry[9].(string) == "val2", "Custom With() was not logged")
   132  
   133  	tearDown()
   134  }
   135  
   136  func TestInfoCutoff(t *testing.T) {
   137  	setUp()
   138  	log := MakeLogger(MockLogger{})
   139  	log.SetLogLevel(WARNING)
   140  	assert(t, log.filterLevel == WARNING, "Unable to set log level")
   141  
   142  	log = log.Level(INFO)
   143  	log.Log("This is an info message")
   144  	assert(t, !logCalled, "Info log entry should not have been recorded")
   145  
   146  	log = log.Level(WARNING)
   147  	log.Log("This is a warning message")
   148  	assert(t, logCalled, "Warning log entry should have been recorded")
   149  	tearDown()
   150  }
   151  
   152  func TestVerbosity(t *testing.T) {
   153  	setUp()
   154  	log := MakeLogger(MockLogger{})
   155  
   156  	assert(t, log.verbosityLevel == 2, "Default verbosity should be 2")
   157  
   158  	if err := log.SetVerbosityLevel(3); err != nil {
   159  		t.Fatal("Unexpected error setting verbosity")
   160  	}
   161  	log.Log("this is a verbosity level 2 message")
   162  	assert(t, logCalled, "Log entry (V=2) should have been recorded")
   163  
   164  	logCalled = false
   165  	vLog := log.V(4)
   166  	vLog.Log("This is a verbosity level 4 message")
   167  	assert(t, !logCalled, "Log entry (V=4) should not have been recorded")
   168  
   169  	// this call should be ignored. repeat last test to prove it
   170  	logCalled = false
   171  	vLog = vLog.V(-1)
   172  	vLog.Log("This is a verbosity level 4 message")
   173  	assert(t, !logCalled, "Log entry (V=4) should not have been recorded")
   174  
   175  	logCalled = false
   176  	vLog.V(3).Log("This is a verbosity level 3 message")
   177  	assert(t, logCalled, "Log entry (V=3) should have been recorded")
   178  
   179  	// once again, this call should do nothing.
   180  	logCalled = false
   181  	vLog = vLog.V(-1)
   182  	vLog.Log("This is a verbosity level 4 message")
   183  	assert(t, !logCalled, "Log entry (V=4) should not have been recorded")
   184  	tearDown()
   185  }
   186  
   187  func TestNegativeVerbosity(t *testing.T) {
   188  	setUp()
   189  	log := MakeLogger(MockLogger{})
   190  	err := log.SetVerbosityLevel(-1)
   191  	assert(t, err != nil, "Requesting a negative verbosity should not have been allowed")
   192  	tearDown()
   193  }
   194  
   195  func TestCachedLoggers(t *testing.T) {
   196  	setUp()
   197  	logger := MockLogger{}
   198  	log := Logger("test")
   199  	log.SetLogger(logger)
   200  
   201  	// set a value on this log class
   202  	log.SetLogLevel(ERROR)
   203  	// obtain a new filtered logger and prove it reflects that same log level
   204  
   205  	log2 := Logger("test")
   206  
   207  	assert(t, log.filterLevel == ERROR, "Log object was not correctly filtered")
   208  	assert(t, log2.filterLevel == ERROR, "Log object was not cached")
   209  	tearDown()
   210  }
   211  
   212  func TestWarningCutoff(t *testing.T) {
   213  	setUp()
   214  	log := MakeLogger(MockLogger{})
   215  
   216  	log.Level(WARNING).Log("message", "test warning message")
   217  	assert(t, logCalled, "Warning level message should have been recorded")
   218  
   219  	log.Level(ERROR).Log("error", "test error message")
   220  	assert(t, logCalled, "Error level message should have been recorded")
   221  	tearDown()
   222  }
   223  
   224  func TestLogConcurrency(t *testing.T) {
   225  	setUp()
   226  	log := MakeLogger(MockLogger{})
   227  	// create a new log object from the previous one.
   228  	log2 := log.Level(WARNING)
   229  	assert(t, log.currentLogLevel != log2.currentLogLevel, "log and log2 should not have the same log level")
   230  	assert(t, log.currentLogLevel == INFO, "Calling Warning() did not create a new log object")
   231  	tearDown()
   232  }
   233  
   234  func TestInfoMessage(t *testing.T) {
   235  	setUp()
   236  	log := MakeLogger(MockLogger{})
   237  	log.SetLogLevel(INFO)
   238  	log.Level(INFO).Log("test", "message")
   239  	logEntry := logParams[0].([]interface{})
   240  	assert(t, logEntry[0].(string) == "level", "Logged line did not have level entry")
   241  	assert(t, logEntry[1].(string) == LogLevelNames[INFO], "Logged line was not infoLevel level")
   242  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   243  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   244  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   245  	tearDown()
   246  }
   247  
   248  func TestWarningMessage(t *testing.T) {
   249  	setUp()
   250  	log := MakeLogger(MockLogger{})
   251  	log.SetLogLevel(WARNING)
   252  	log.Level(WARNING).Log("test", "message")
   253  	logEntry := logParams[0].([]interface{})
   254  	assert(t, logEntry[0].(string) == "level", "Logged line did not have level entry")
   255  	assert(t, logEntry[1].(string) == LogLevelNames[WARNING], "Logged line was not warningLevel level")
   256  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   257  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   258  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   259  	tearDown()
   260  }
   261  
   262  func TestErrorMessage(t *testing.T) {
   263  	setUp()
   264  	log := MakeLogger(MockLogger{})
   265  	log.SetLogLevel(ERROR)
   266  	log.Level(ERROR).Log("test", "message")
   267  	logEntry := logParams[0].([]interface{})
   268  	assert(t, logEntry[0].(string) == "level", "Logged line did not have level entry")
   269  	assert(t, logEntry[1].(string) == LogLevelNames[ERROR], "Logged line was not errorLevel level")
   270  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   271  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   272  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   273  	tearDown()
   274  }
   275  
   276  func TestCriticalMessage(t *testing.T) {
   277  	setUp()
   278  	log := MakeLogger(MockLogger{})
   279  	log.SetLogLevel(FATAL)
   280  	log.Level(FATAL).Log("test", "message")
   281  	logEntry := logParams[0].([]interface{})
   282  	assert(t, logEntry[0].(string) == "level", "Logged line did not have level entry")
   283  	assert(t, logEntry[1].(string) == LogLevelNames[FATAL], "Logged line was not fatalLevel level")
   284  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   285  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   286  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   287  	tearDown()
   288  }
   289  
   290  func TestObject(t *testing.T) {
   291  	setUp()
   292  	log := MakeLogger(MockLogger{})
   293  	log.SetLogLevel(INFO)
   294  	vm := v1.VirtualMachineInstance{ObjectMeta: v12.ObjectMeta{Namespace: "test"}}
   295  	log.Object(&vm).Log("test", "message")
   296  	logEntry := logParams[0].([]interface{})
   297  	assert(t, logEntry[0].(string) == "level", "Logged line did not have level entry")
   298  	assert(t, logEntry[1].(string) == LogLevelNames[INFO], "Logged line was not of level infoLevel")
   299  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   300  	assert(t, logEntry[4].(string) == "pos", "Logged line was not pos")
   301  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   302  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   303  	assert(t, logEntry[8].(string) == "namespace", "Logged line did not contain object namespace")
   304  	assert(t, logEntry[10].(string) == "name", "Logged line did not contain object name")
   305  	assert(t, logEntry[12].(string) == "kind", "Logged line did not contain object kind")
   306  	assert(t, logEntry[14].(string) == "uid", "Logged line did not contain UUID")
   307  	tearDown()
   308  }
   309  
   310  func TestError(t *testing.T) {
   311  	setUp()
   312  	log := MakeLogger(MockLogger{})
   313  	log.SetLogLevel(INFO)
   314  	err := errors.New("Test error")
   315  	log.Level(ERROR).Log(err)
   316  	assert(t, logCalled, "Error was not logged via .Log()")
   317  
   318  	logCalled = false
   319  	log.msg(err)
   320  	assert(t, logCalled, "Error was not logged via .msg()")
   321  
   322  	logCalled = false
   323  	// using more than one parameter in format string
   324  	log.msgf("[%d] %s", 1, err)
   325  	assert(t, logCalled, "Error was not logged via .msgf()")
   326  
   327  	logCalled = false
   328  	log.msgf("%s", err)
   329  	assert(t, logCalled, "Error was not logged via .msgf()")
   330  	tearDown()
   331  }
   332  
   333  func TestMultipleLevels(t *testing.T) {
   334  	setUp()
   335  	log := MakeLogger(MockLogger{})
   336  	log.SetLogLevel(INFO)
   337  	// change levels more than once
   338  	log.Level(WARNING).Level(INFO).Level(WARNING).msg("test")
   339  
   340  	logEntry := logParams[0].([]interface{})
   341  	assert(t, logEntry[0].(string) == "level", "Logged line did not have level entry")
   342  	assert(t, logEntry[1].(string) == LogLevelNames[WARNING], "Logged line was not of level warningLevel")
   343  	assert(t, logEntry[2].(string) == "timestamp", "Logged line is not expected format")
   344  	assert(t, logEntry[4].(string) == "pos", "Logged line was not pos")
   345  	assert(t, logEntry[6].(string) == "component", "Logged line is not expected format")
   346  	assert(t, logEntry[7].(string) == "test", "Component was not logged")
   347  	assert(t, logEntry[8].(string) == "msg", "Logged line did not contain message header")
   348  	assert(t, logEntry[9].(string) == "test", "Logged line did not contain message")
   349  	tearDown()
   350  }
   351  
   352  func TestLogVerbosity(t *testing.T) {
   353  	setUp()
   354  	log := MakeLogger(MockLogger{})
   355  	log.SetLogLevel(INFO)
   356  	log.SetVerbosityLevel(2)
   357  
   358  	// Filtered Logger
   359  	assert(t, log.Verbosity(2), "Verbosity should match")
   360  	assert(t, log.Verbosity(1), "Actual verbosity is higher")
   361  	assert(t, !log.Verbosity(3), "Verbosity is lower")
   362  
   363  	// Filtered Verbosity Logger
   364  	assert(t, log.V(2).Verbosity(2), "Verbosity should match")
   365  	assert(t, log.V(2).Verbosity(1), "Actual verbosity is higher")
   366  	assert(t, !log.V(2).Verbosity(3), "Verbosity is lower")
   367  
   368  	log.V(2).Log("msg", "test")
   369  	logEntry := logParams[0].([]interface{})
   370  	assert(t, logEntry[4].(string) == "pos", "Logged line did not contain pos")
   371  	assert(t, strings.HasPrefix(logEntry[5].(string), "log_test.go"), "Logged line referenced wrong module")
   372  	tearDown()
   373  }
   374  
   375  func TestErrWithMsgf(t *testing.T) {
   376  	setUp()
   377  	log := MakeLogger(MockLogger{})
   378  	log.Reason(fmt.Errorf("testerror")).msgf("%s", "test")
   379  
   380  	logEntry := logParams[0].([]interface{})
   381  	assert(t, logEntry[8].(string) == "reason", "Logged line did not contain message header")
   382  	assert(t, logEntry[9].(error).Error() == "testerror", "Logged line did not contain message header")
   383  	assert(t, logEntry[10].(string) == "msg", "Logged line did not contain message header")
   384  	assert(t, logEntry[11].(string) == "test", "Logged line did not contain message")
   385  	tearDown()
   386  }
   387
View as plain text