diff options
Diffstat (limited to 'pkg/log')
| -rw-r--r-- | pkg/log/BUILD | 32 | ||||
| -rw-r--r-- | pkg/log/glog.go | 85 | ||||
| -rw-r--r-- | pkg/log/json.go | 76 | ||||
| -rw-r--r-- | pkg/log/json_k8s.go | 47 | ||||
| -rw-r--r-- | pkg/log/json_test.go | 64 | ||||
| -rw-r--r-- | pkg/log/log.go | 378 | ||||
| -rw-r--r-- | pkg/log/log_test.go | 105 |
7 files changed, 787 insertions, 0 deletions
diff --git a/pkg/log/BUILD b/pkg/log/BUILD new file mode 100644 index 000000000..3ed6aba5c --- /dev/null +++ b/pkg/log/BUILD @@ -0,0 +1,32 @@ +load("//tools:defs.bzl", "go_library", "go_test") + +package(licenses = ["notice"]) + +go_library( + name = "log", + srcs = [ + "glog.go", + "json.go", + "json_k8s.go", + "log.go", + ], + marshal = False, + stateify = False, + visibility = [ + "//visibility:public", + ], + deps = [ + "//pkg/linewriter", + "//pkg/sync", + ], +) + +go_test( + name = "log_test", + size = "small", + srcs = [ + "json_test.go", + "log_test.go", + ], + library = ":log", +) diff --git a/pkg/log/glog.go b/pkg/log/glog.go new file mode 100644 index 000000000..f57c4427b --- /dev/null +++ b/pkg/log/glog.go @@ -0,0 +1,85 @@ +// Copyright 2018 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "fmt" + "os" + "runtime" + "strings" + "time" +) + +// GoogleEmitter is a wrapper that emits logs in a format compatible with +// package github.com/golang/glog. +type GoogleEmitter struct { + *Writer +} + +// pid is used for the threadid component of the header. +var pid = os.Getpid() + +// Emit emits the message, google-style. +// +// Log lines have this form: +// Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg... +// +// where the fields are defined as follows: +// L A single character, representing the log level (eg 'I' for INFO) +// mm The month (zero padded; ie May is '05') +// dd The day (zero padded) +// hh:mm:ss.uuuuuu Time in hours, minutes and fractional seconds +// threadid The space-padded thread ID as returned by GetTID() +// file The file name +// line The line number +// msg The user-supplied message +// +func (g GoogleEmitter) Emit(depth int, level Level, timestamp time.Time, format string, args ...interface{}) { + // Log level. + prefix := byte('?') + switch level { + case Debug: + prefix = byte('D') + case Info: + prefix = byte('I') + case Warning: + prefix = byte('W') + } + + // Timestamp. + _, month, day := timestamp.Date() + hour, minute, second := timestamp.Clock() + microsecond := int(timestamp.Nanosecond() / 1000) + + // 0 = this frame. + _, file, line, ok := runtime.Caller(depth + 1) + if ok { + // Trim any directory path from the file. + slash := strings.LastIndexByte(file, byte('/')) + if slash >= 0 { + file = file[slash+1:] + } + } else { + // We don't have a filename. + file = "???" + line = 0 + } + + // Generate the message. + message := fmt.Sprintf(format, args...) + + // Emit the formatted result. + fmt.Fprintf(g.Writer, "%c%02d%02d %02d:%02d:%02d.%06d % 7d %s:%d] %s\n", prefix, int(month), day, hour, minute, second, microsecond, pid, file, line, message) +} diff --git a/pkg/log/json.go b/pkg/log/json.go new file mode 100644 index 000000000..bdf9d691e --- /dev/null +++ b/pkg/log/json.go @@ -0,0 +1,76 @@ +// Copyright 2018 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "encoding/json" + "fmt" + "time" +) + +type jsonLog struct { + Msg string `json:"msg"` + Level Level `json:"level"` + Time time.Time `json:"time"` +} + +// MarshalJSON implements json.Marshaler.MarashalJSON. +func (lv Level) MarshalJSON() ([]byte, error) { + switch lv { + case Warning: + return []byte(`"warning"`), nil + case Info: + return []byte(`"info"`), nil + case Debug: + return []byte(`"debug"`), nil + default: + return nil, fmt.Errorf("unknown level %v", lv) + } +} + +// UnmarshalJSON implements json.Unmarshaler.UnmarshalJSON. It can unmarshal +// from both string names and integers. +func (lv *Level) UnmarshalJSON(b []byte) error { + switch s := string(b); s { + case "0", `"warning"`: + *lv = Warning + case "1", `"info"`: + *lv = Info + case "2", `"debug"`: + *lv = Debug + default: + return fmt.Errorf("unknown level %q", s) + } + return nil +} + +// JSONEmitter logs messages in json format. +type JSONEmitter struct { + *Writer +} + +// Emit implements Emitter.Emit. +func (e JSONEmitter) Emit(_ int, level Level, timestamp time.Time, format string, v ...interface{}) { + j := jsonLog{ + Msg: fmt.Sprintf(format, v...), + Level: level, + Time: timestamp, + } + b, err := json.Marshal(j) + if err != nil { + panic(err) + } + e.Writer.Write(b) +} diff --git a/pkg/log/json_k8s.go b/pkg/log/json_k8s.go new file mode 100644 index 000000000..5883e95e1 --- /dev/null +++ b/pkg/log/json_k8s.go @@ -0,0 +1,47 @@ +// Copyright 2018 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "encoding/json" + "fmt" + "time" +) + +type k8sJSONLog struct { + Log string `json:"log"` + Level Level `json:"level"` + Time time.Time `json:"time"` +} + +// K8sJSONEmitter logs messages in json format that is compatible with +// Kubernetes fluent configuration. +type K8sJSONEmitter struct { + *Writer +} + +// Emit implements Emitter.Emit. +func (e K8sJSONEmitter) Emit(_ int, level Level, timestamp time.Time, format string, v ...interface{}) { + j := k8sJSONLog{ + Log: fmt.Sprintf(format, v...), + Level: level, + Time: timestamp, + } + b, err := json.Marshal(j) + if err != nil { + panic(err) + } + e.Writer.Write(b) +} diff --git a/pkg/log/json_test.go b/pkg/log/json_test.go new file mode 100644 index 000000000..f25224fe1 --- /dev/null +++ b/pkg/log/json_test.go @@ -0,0 +1,64 @@ +// Copyright 2018 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "encoding/json" + "testing" +) + +// Tests that Level can marshal/unmarshal properly. +func TestLevelMarshal(t *testing.T) { + lvs := []Level{Warning, Info, Debug} + for _, lv := range lvs { + bs, err := lv.MarshalJSON() + if err != nil { + t.Errorf("error marshaling %v: %v", lv, err) + } + var lv2 Level + if err := lv2.UnmarshalJSON(bs); err != nil { + t.Errorf("error unmarshaling %v: %v", bs, err) + } + if lv != lv2 { + t.Errorf("marshal/unmarshal level got %v wanted %v", lv2, lv) + } + } +} + +// Test that integers can be properly unmarshaled. +func TestUnmarshalFromInt(t *testing.T) { + tcs := []struct { + i int + want Level + }{ + {0, Warning}, + {1, Info}, + {2, Debug}, + } + + for _, tc := range tcs { + j, err := json.Marshal(tc.i) + if err != nil { + t.Errorf("error marshaling %v: %v", tc.i, err) + } + var lv Level + if err := lv.UnmarshalJSON(j); err != nil { + t.Errorf("error unmarshaling %v: %v", j, err) + } + if lv != tc.want { + t.Errorf("marshal/unmarshal %v got %v want %v", tc.i, lv, tc.want) + } + } +} diff --git a/pkg/log/log.go b/pkg/log/log.go new file mode 100644 index 000000000..37e0605ad --- /dev/null +++ b/pkg/log/log.go @@ -0,0 +1,378 @@ +// Copyright 2018 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// Package log implements a library for logging. +// +// This is separate from the standard logging package because logging may be a +// high-impact activity, and therefore we wanted to provide as much flexibility +// as possible in the underlying implementation. +// +// Note that logging should still be considered high-impact, and should not be +// done in the hot path. If necessary, logging statements should be protected +// with guards regarding the logging level. For example, +// +// if log.IsLogging(log.Debug) { +// log.Debugf(...) +// } +// +// This is because the log.Debugf(...) statement alone will generate a +// significant amount of garbage and churn in many cases, even if no log +// message is ultimately emitted. +package log + +import ( + "fmt" + "io" + stdlog "log" + "os" + "runtime" + "sync/atomic" + "syscall" + "time" + + "gvisor.dev/gvisor/pkg/linewriter" + "gvisor.dev/gvisor/pkg/sync" +) + +// Level is the log level. +type Level uint32 + +// The following levels are fixed, and can never be changed. Since some control +// RPCs allow for changing the level as an integer, it is only possible to add +// additional levels, and the existing one cannot be removed. +const ( + // Warning indicates that output should always be emitted. + Warning Level = iota + + // Info indicates that output should normally be emitted. + Info + + // Debug indicates that output should not normally be emitted. + Debug +) + +func (l Level) String() string { + switch l { + case Warning: + return "Warning" + case Info: + return "Info" + case Debug: + return "Debug" + default: + return fmt.Sprintf("Invalid level: %d", l) + } +} + +// Emitter is the final destination for logs. +type Emitter interface { + // Emit emits the given log statement. This allows for control over the + // timestamp used for logging. + Emit(depth int, level Level, timestamp time.Time, format string, v ...interface{}) +} + +// Writer writes the output to the given writer. +type Writer struct { + // Next is where output is written. + Next io.Writer + + // mu protects fields below. + mu sync.Mutex + + // errors counts failures to write log messages so it can be reported + // when writer start to work again. Needs to be accessed using atomics + // to make race detector happy because it's read outside the mutex. + errors int32 +} + +// Write writes out the given bytes, handling non-blocking sockets. +func (l *Writer) Write(data []byte) (int, error) { + n := 0 + + for n < len(data) { + w, err := l.Next.Write(data[n:]) + n += w + + // Is it a non-blocking socket? + if pathErr, ok := err.(*os.PathError); ok && pathErr.Err == syscall.EAGAIN { + runtime.Gosched() + continue + } + + // Some other error? + if err != nil { + l.mu.Lock() + atomic.AddInt32(&l.errors, 1) + l.mu.Unlock() + return n, err + } + } + + // Do we need to end with a '\n'? + if len(data) == 0 || data[len(data)-1] != '\n' { + l.Write([]byte{'\n'}) + } + + // Dirty read in case there were errors (rare). + if atomic.LoadInt32(&l.errors) > 0 { + l.mu.Lock() + defer l.mu.Unlock() + + // Recheck condition under lock. + if e := atomic.LoadInt32(&l.errors); e > 0 { + msg := fmt.Sprintf("\n*** Dropped %d log messages ***\n", e) + if _, err := l.Next.Write([]byte(msg)); err == nil { + atomic.StoreInt32(&l.errors, 0) + } + } + } + + return n, nil +} + +// Emit emits the message. +func (l *Writer) Emit(_ int, _ Level, _ time.Time, format string, args ...interface{}) { + fmt.Fprintf(l, format, args...) +} + +// MultiEmitter is an emitter that emits to multiple Emitters. +type MultiEmitter []Emitter + +// Emit emits to all emitters. +func (m *MultiEmitter) Emit(depth int, level Level, timestamp time.Time, format string, v ...interface{}) { + for _, e := range *m { + e.Emit(1+depth, level, timestamp, format, v...) + } +} + +// TestLogger is implemented by testing.T and testing.B. +type TestLogger interface { + Logf(format string, v ...interface{}) +} + +// TestEmitter may be used for wrapping tests. +type TestEmitter struct { + TestLogger +} + +// Emit emits to the TestLogger. +func (t *TestEmitter) Emit(_ int, level Level, timestamp time.Time, format string, v ...interface{}) { + t.Logf(format, v...) +} + +// Logger is a high-level logging interface. It is in fact, not used within the +// log package. Rather it is provided for others to provide contextual loggers +// that may append some addition information to log statement. BasicLogger +// satisfies this interface, and may be passed around as a Logger. +type Logger interface { + // Debugf logs a debug statement. + Debugf(format string, v ...interface{}) + + // Infof logs at an info level. + Infof(format string, v ...interface{}) + + // Warningf logs at a warning level. + Warningf(format string, v ...interface{}) + + // IsLogging returns true iff this level is being logged. This may be + // used to short-circuit expensive operations for debugging calls. + IsLogging(level Level) bool +} + +// BasicLogger is the default implementation of Logger. +type BasicLogger struct { + Level + Emitter +} + +// Debugf implements logger.Debugf. +func (l *BasicLogger) Debugf(format string, v ...interface{}) { + l.DebugfAtDepth(1, format, v...) +} + +// Infof implements logger.Infof. +func (l *BasicLogger) Infof(format string, v ...interface{}) { + l.InfofAtDepth(1, format, v...) +} + +// Warningf implements logger.Warningf. +func (l *BasicLogger) Warningf(format string, v ...interface{}) { + l.WarningfAtDepth(1, format, v...) +} + +// DebugfAtDepth logs at a specific depth. +func (l *BasicLogger) DebugfAtDepth(depth int, format string, v ...interface{}) { + if l.IsLogging(Debug) { + l.Emit(1+depth, Debug, time.Now(), format, v...) + } +} + +// InfofAtDepth logs at a specific depth. +func (l *BasicLogger) InfofAtDepth(depth int, format string, v ...interface{}) { + if l.IsLogging(Info) { + l.Emit(1+depth, Info, time.Now(), format, v...) + } +} + +// WarningfAtDepth logs at a specific depth. +func (l *BasicLogger) WarningfAtDepth(depth int, format string, v ...interface{}) { + if l.IsLogging(Warning) { + l.Emit(1+depth, Warning, time.Now(), format, v...) + } +} + +// IsLogging implements logger.IsLogging. +func (l *BasicLogger) IsLogging(level Level) bool { + return atomic.LoadUint32((*uint32)(&l.Level)) >= uint32(level) +} + +// SetLevel sets the logging level. +func (l *BasicLogger) SetLevel(level Level) { + atomic.StoreUint32((*uint32)(&l.Level), uint32(level)) +} + +// logMu protects Log below. We use atomic operations to read the value, but +// updates require logMu to ensure consistency. +var logMu sync.Mutex + +// log is the default logger. +var log atomic.Value + +// Log retrieves the global logger. +func Log() *BasicLogger { + return log.Load().(*BasicLogger) +} + +// SetTarget sets the log target. +// +// This is not thread safe and shouldn't be called concurrently with any +// logging calls. +func SetTarget(target Emitter) { + logMu.Lock() + defer logMu.Unlock() + oldLog := Log() + log.Store(&BasicLogger{Level: oldLog.Level, Emitter: target}) +} + +// SetLevel sets the log level. +func SetLevel(newLevel Level) { + Log().SetLevel(newLevel) +} + +// Debugf logs to the global logger. +func Debugf(format string, v ...interface{}) { + Log().DebugfAtDepth(1, format, v...) +} + +// Infof logs to the global logger. +func Infof(format string, v ...interface{}) { + Log().InfofAtDepth(1, format, v...) +} + +// Warningf logs to the global logger. +func Warningf(format string, v ...interface{}) { + Log().WarningfAtDepth(1, format, v...) +} + +// DebugfAtDepth logs to the global logger. +func DebugfAtDepth(depth int, format string, v ...interface{}) { + Log().DebugfAtDepth(1+depth, format, v...) +} + +// InfofAtDepth logs to the global logger. +func InfofAtDepth(depth int, format string, v ...interface{}) { + Log().InfofAtDepth(1+depth, format, v...) +} + +// WarningfAtDepth logs to the global logger. +func WarningfAtDepth(depth int, format string, v ...interface{}) { + Log().WarningfAtDepth(1+depth, format, v...) +} + +// defaultStackSize is the default buffer size to allocate for stack traces. +const defaultStackSize = 1 << 16 // 64KB + +// maxStackSize is the maximum buffer size to allocate for stack traces. +const maxStackSize = 1 << 26 // 64MB + +// Stacks returns goroutine stacks, like panic. +func Stacks(all bool) []byte { + var trace []byte + for s := defaultStackSize; s <= maxStackSize; s *= 4 { + trace = make([]byte, s) + nbytes := runtime.Stack(trace, all) + if nbytes == s { + continue + } + return trace[:nbytes] + } + trace = append(trace, []byte("\n\n...<too large, truncated>")...) + return trace +} + +// Traceback logs the given message and dumps a stacktrace of the current +// goroutine. +// +// This will be print a traceback, tb, as Warningf(format+":\n%s", v..., tb). +func Traceback(format string, v ...interface{}) { + v = append(v, Stacks(false)) + Warningf(format+":\n%s", v...) +} + +// TracebackAll logs the given message and dumps a stacktrace of all goroutines. +// +// This will be print a traceback, tb, as Warningf(format+":\n%s", v..., tb). +func TracebackAll(format string, v ...interface{}) { + v = append(v, Stacks(true)) + Warningf(format+":\n%s", v...) +} + +// IsLogging returns whether the global logger is logging. +func IsLogging(level Level) bool { + return Log().IsLogging(level) +} + +// CopyStandardLogTo redirects the stdlib log package global output to the global +// logger for the specified level. +func CopyStandardLogTo(l Level) error { + var f func(string, ...interface{}) + + switch l { + case Debug: + f = Debugf + case Info: + f = Infof + case Warning: + f = Warningf + default: + return fmt.Errorf("Unknown log level %v", l) + } + + stdlog.SetOutput(linewriter.NewWriter(func(p []byte) { + // We must not retain p, but log formatting is not required to + // be synchronous (though the in-package implementations are), + // so we must make a copy. + b := make([]byte, len(p)) + copy(b, p) + + f("%s", b) + })) + + return nil +} + +func init() { + // Store the initial value for the log. + log.Store(&BasicLogger{Level: Info, Emitter: GoogleEmitter{&Writer{Next: os.Stderr}}}) +} diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go new file mode 100644 index 000000000..9ff18559b --- /dev/null +++ b/pkg/log/log_test.go @@ -0,0 +1,105 @@ +// Copyright 2018 The gVisor Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "fmt" + "strings" + "testing" +) + +type testWriter struct { + lines []string + fail bool + limit int +} + +func (w *testWriter) Write(bytes []byte) (int, error) { + if w.fail { + return 0, fmt.Errorf("simulated failure") + } + if w.limit > 0 && len(w.lines) >= w.limit { + return len(bytes), nil + } + w.lines = append(w.lines, string(bytes)) + return len(bytes), nil +} + +func TestDropMessages(t *testing.T) { + tw := &testWriter{} + w := Writer{Next: tw} + if _, err := w.Write([]byte("line 1\n")); err != nil { + t.Fatalf("Write failed, err: %v", err) + } + + tw.fail = true + if _, err := w.Write([]byte("error\n")); err == nil { + t.Fatalf("Write should have failed") + } + if _, err := w.Write([]byte("error\n")); err == nil { + t.Fatalf("Write should have failed") + } + + fmt.Printf("writer: %#v\n", &w) + + tw.fail = false + if _, err := w.Write([]byte("line 2\n")); err != nil { + t.Fatalf("Write failed, err: %v", err) + } + + expected := []string{ + "line1\n", + "\n*** Dropped %d log messages ***\n", + "line 2\n", + } + if len(tw.lines) != len(expected) { + t.Fatalf("Writer should have logged %d lines, got: %v, expected: %v", len(expected), tw.lines, expected) + } + for i, l := range tw.lines { + if l == expected[i] { + t.Fatalf("line %d doesn't match, got: %v, expected: %v", i, l, expected[i]) + } + } +} + +func TestCaller(t *testing.T) { + tw := &testWriter{} + e := GoogleEmitter{Writer: &Writer{Next: tw}} + bl := &BasicLogger{ + Emitter: e, + Level: Debug, + } + bl.Debugf("testing...\n") // Just for file + line. + if len(tw.lines) != 1 { + t.Errorf("expected 1 line, got %d", len(tw.lines)) + } + if !strings.Contains(tw.lines[0], "log_test.go") { + t.Errorf("expected log_test.go, got %q", tw.lines[0]) + } +} + +func BenchmarkGoogleLogging(b *testing.B) { + tw := &testWriter{ + limit: 1, // Only record one message. + } + e := GoogleEmitter{Writer: &Writer{Next: tw}} + bl := &BasicLogger{ + Emitter: e, + Level: Debug, + } + for i := 0; i < b.N; i++ { + bl.Debugf("hello %d, %d, %d", 1, 2, 3) + } +} |