Skip to content

Commit

Permalink
Log timestamp
Browse files Browse the repository at this point in the history
  • Loading branch information
@rmohr
rmohr committed Jan 12, 2017
1 parent 8228f4d commit a58b2bf
Show file tree
Hide file tree
Showing 2 changed files with 61 additions and 47 deletions.
13 changes: 9 additions & 4 deletions pkg/logging/logging.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import (
"path/filepath"
"runtime"
"strconv"
"time"
)

type logLevel int
Expand Down Expand Up @@ -125,11 +126,15 @@ func (l FilteredLogger) log(skipFrames int, params ...interface{}) error {
if force || (l.filterLevel == INFO &&
(l.currentLogLevel == l.filterLevel) &&
(l.currentVerbosityLevel <= l.verbosityLevel)) {
logParams := make([]interface{}, 0)

logParams = append(logParams, "component", l.component, "level", logLevelNames[l.currentLogLevel])
now := time.Now().UTC()
_, fileName, lineNumber, _ := runtime.Caller(skipFrames)
logParams = append(logParams, "pos", fmt.Sprintf("%s:%d", filepath.Base(fileName), lineNumber))
logParams := make([]interface{}, 0, 8)

logParams = append(logParams,
"timestamp", now.Format("2006-01-02T15:04:05.000000Z"),
"component", l.component,
"level", logLevelNames[l.currentLogLevel],
"pos", fmt.Sprintf("%s:%d", filepath.Base(fileName), lineNumber))
return l.logContext.WithPrefix(logParams...).Log(params...)
}
return nil
Expand Down
95 changes: 52 additions & 43 deletions pkg/logging/logging_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ import (
"kubevirt.io/kubevirt/pkg/api"
"path/filepath"
"runtime"
"strings"
"testing"
)

Expand Down Expand Up @@ -83,8 +84,9 @@ func TestComponent(t *testing.T) {
assert(t, len(logParams) == 1, "Expected 1 log line")

logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
tearDown()
}

Expand Down Expand Up @@ -206,10 +208,11 @@ func TestDebugMessage(t *testing.T) {
log.SetLogLevel(DEBUG)
log.Debug().Log("test", "message")
logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "DEBUG", "Logged line was not DEBUG level")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "DEBUG", "Logged line was not DEBUG level")
tearDown()
}

Expand All @@ -219,10 +222,11 @@ func TestInfoMessage(t *testing.T) {
log.SetLogLevel(DEBUG)
log.Info().Log("test", "message")
logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "INFO", "Logged line was not INFO level")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "INFO", "Logged line was not INFO level")
tearDown()
}

Expand All @@ -232,10 +236,11 @@ func TestWarningMessage(t *testing.T) {
log.SetLogLevel(DEBUG)
log.Warning().Log("test", "message")
logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "WARNING", "Logged line was not WARNING level")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "WARNING", "Logged line was not WARNING level")
tearDown()
}

Expand All @@ -245,10 +250,11 @@ func TestErrorMessage(t *testing.T) {
log.SetLogLevel(DEBUG)
log.Error().Log("test", "message")
logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "ERROR", "Logged line was not ERROR level")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "ERROR", "Logged line was not ERROR level")
tearDown()
}

Expand All @@ -258,10 +264,11 @@ func TestCriticalMessage(t *testing.T) {
log.SetLogLevel(DEBUG)
log.Critical().Log("test", "message")
logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "CRITICAL", "Logged line was not CRITICAL level")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "CRITICAL", "Logged line was not CRITICAL level")
tearDown()
}

Expand All @@ -272,14 +279,15 @@ func TestObject(t *testing.T) {
vm := api.VM{}
log.Object(&vm).Log("test", "message")
logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "INFO", "Logged line was not of level INFO")
assert(t, logEntry[4].(string) == "pos", "Logged line was not pos")
assert(t, logEntry[6].(string) == "name", "Logged line did not contain object name")
assert(t, logEntry[8].(string) == "kind", "Logged line did not contain object kind")
assert(t, logEntry[10].(string) == "uid", "Logged line did not contain UUID")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "INFO", "Logged line was not of level INFO")
assert(t, logEntry[6].(string) == "pos", "Logged line was not pos")
assert(t, logEntry[8].(string) == "name", "Logged line did not contain object name")
assert(t, logEntry[10].(string) == "kind", "Logged line did not contain object kind")
assert(t, logEntry[12].(string) == "uid", "Logged line did not contain UUID")
tearDown()
}

Expand Down Expand Up @@ -314,13 +322,14 @@ func TestMultipleLevels(t *testing.T) {
log.Info().Debug().Info().Msg("test")

logEntry := logParams[0].([]interface{})
assert(t, logEntry[0].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[1].(string) == "test", "Component was not logged")
assert(t, logEntry[2].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[3].(string) == "INFO", "Logged line was not of level INFO")
assert(t, logEntry[4].(string) == "pos", "Logged line was not pos")
assert(t, logEntry[6].(string) == "msg", "Logged line did not contain message header")
assert(t, logEntry[7].(string) == "test", "Logged line did not contain message")
assert(t, logEntry[0].(string) == "timestamp", "Logged line is not expected format")
assert(t, logEntry[2].(string) == "component", "Logged line is not expected format")
assert(t, logEntry[3].(string) == "test", "Component was not logged")
assert(t, logEntry[4].(string) == "level", "Logged line did not have level entry")
assert(t, logEntry[5].(string) == "INFO", "Logged line was not of level INFO")
assert(t, logEntry[6].(string) == "pos", "Logged line was not pos")
assert(t, logEntry[8].(string) == "msg", "Logged line did not contain message header")
assert(t, logEntry[9].(string) == "test", "Logged line did not contain message")
tearDown()
}

Expand All @@ -332,8 +341,8 @@ func TestLogVerbosity(t *testing.T) {
log.V(2).Log("msg", "test")

logEntry := logParams[0].([]interface{})
assert(t, logEntry[4].(string) == "filename", "Logged line did not contain filename")
assert(t, logEntry[5].(string) == "logging_test.go", "Logged line referenced wrong module")
assert(t, logEntry[6].(string) == "pos", "Logged line did not contain pos")
assert(t, strings.HasPrefix(logEntry[7].(string), "logging_test.go"), "Logged line referenced wrong module")
tearDown()
}

Expand All @@ -345,8 +354,8 @@ func TestMsgVerbosity(t *testing.T) {
log.V(2).Msg("test")

logEntry := logParams[0].([]interface{})
assert(t, logEntry[4].(string) == "filename", "Logged line did not contain filename")
assert(t, logEntry[5].(string) == "logging_test.go", "Logged line referenced wrong module")
assert(t, logEntry[6].(string) == "pos", "Logged line did not contain pos")
assert(t, strings.HasPrefix(logEntry[7].(string), "logging_test.go"), "Logged line referenced wrong module")
tearDown()
}

Expand All @@ -358,7 +367,7 @@ func TestMsgfVerbosity(t *testing.T) {
log.V(2).Msgf("%s", "test")

logEntry := logParams[0].([]interface{})
assert(t, logEntry[4].(string) == "filename", "Logged line did not contain filename")
assert(t, logEntry[5].(string) == "logging_test.go", "Logged line referenced wrong module")
assert(t, logEntry[6].(string) == "pos", "Logged line did not contain pos")
assert(t, strings.HasPrefix(logEntry[7].(string), "logging_test.go"), "Logged line referenced wrong module")
tearDown()
}

0 comments on commit a58b2bf

Please sign in to comment.