Merge branch 'master' into ipt-udp-matchers

6 files changed, 98 insertions, 162 deletions

diff --git a/pkg/log/BUILD b/pkg/log/BUILD
index 0df0f2849..a7c8f7bef 100644
--- a/pkg/log/BUILD
+++ b/pkg/log/BUILD
@@ -1,5 +1,4 @@
-load("//tools/go_stateify:defs.bzl", "go_library")
-load("@io_bazel_rules_go//go:def.bzl", "go_test")
+load("//tools:defs.bzl", "go_library", "go_test")
 
 package(licenses = ["notice"])
 
@@ -7,12 +6,10 @@ go_library(
     name = "log",
     srcs = [
         "glog.go",
-        "glog_unsafe.go",
         "json.go",
         "json_k8s.go",
         "log.go",
     ],
-    importpath = "gvisor.dev/gvisor/pkg/log",
     visibility = [
         "//visibility:public",
     ],
@@ -29,5 +26,5 @@ go_test(
         "json_test.go",
         "log_test.go",
     ],
-    embed = [":log"],
+    library = ":log",
 )
diff --git a/pkg/log/glog.go b/pkg/log/glog.go
index 5732785b4..cab5fae55 100644
--- a/pkg/log/glog.go
+++ b/pkg/log/glog.go
@@ -15,149 +15,73 @@
 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 {
-	// Emitter is the underlying emitter.
-	Emitter
-}
-
-// buffer is a simple inline buffer to avoid churn. The data slice is generally
-// kept to the local byte array, and we avoid having to allocate it on the heap.
-type buffer struct {
-	local [256]byte
-	data  []byte
-}
-
-func (b *buffer) start() {
-	b.data = b.local[:0]
-}
-
-func (b *buffer) String() string {
-	return unsafeString(b.data)
-}
-
-func (b *buffer) write(c byte) {
-	b.data = append(b.data, c)
-}
-
-func (b *buffer) writeAll(d []byte) {
-	b.data = append(b.data, d...)
-}
-
-func (b *buffer) writeOneDigit(d byte) {
-	b.write('0' + d)
-}
-
-func (b *buffer) writeTwoDigits(v int) {
-	v = v % 100
-	b.writeOneDigit(byte(v / 10))
-	b.writeOneDigit(byte(v % 10))
-}
-
-func (b *buffer) writeSixDigits(v int) {
-	v = v % 1000000
-	b.writeOneDigit(byte(v / 100000))
-	b.writeOneDigit(byte((v % 100000) / 10000))
-	b.writeOneDigit(byte((v % 10000) / 1000))
-	b.writeOneDigit(byte((v % 1000) / 100))
-	b.writeOneDigit(byte((v % 100) / 10))
-	b.writeOneDigit(byte(v % 10))
-}
-
-func calculateBytes(v int, pad int) []byte {
-	var d []byte
-	r := 1
-
-	for n := 10; v >= r; n = n * 10 {
-		d = append(d, '0'+byte((v%n)/r))
-		r = n
-	}
-
-	for i := len(d); i < pad; i++ {
-		d = append(d, ' ')
-	}
-
-	for i := 0; i < len(d)/2; i++ {
-		d[i], d[len(d)-(i+1)] = d[len(d)-(i+1)], d[i]
-	}
-	return d
+	Writer
 }
 
 // pid is used for the threadid component of the header.
-//
-// The glog package logger uses 7 spaces of padding. See
-// glob.loggingT.formatHeader.
-var pid = calculateBytes(os.Getpid(), 7)
-
-// caller is faked out as the caller. See FIXME below.
-var caller = []byte("x:0")
+var pid = os.Getpid()
 
 // Emit emits the message, google-style.
-func (g GoogleEmitter) Emit(level Level, timestamp time.Time, format string, args ...interface{}) {
-	var b buffer
-	b.start()
-
-	// 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
-
+//
+// 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(level Level, timestamp time.Time, format string, args ...interface{}) {
 	// Log level.
+	prefix := byte('?')
 	switch level {
 	case Debug:
-		b.write('D')
+		prefix = byte('D')
 	case Info:
-		b.write('I')
+		prefix = byte('I')
 	case Warning:
-		b.write('W')
+		prefix = byte('W')
 	}
 
 	// Timestamp.
 	_, month, day := timestamp.Date()
 	hour, minute, second := timestamp.Clock()
-	b.writeTwoDigits(int(month))
-	b.writeTwoDigits(int(day))
-	b.write(' ')
-	b.writeTwoDigits(int(hour))
-	b.write(':')
-	b.writeTwoDigits(int(minute))
-	b.write(':')
-	b.writeTwoDigits(int(second))
-	b.write('.')
-	b.writeSixDigits(int(timestamp.Nanosecond() / 1000))
-	b.write(' ')
-
-	// The pid.
-	b.writeAll(pid)
-	b.write(' ')
-
-	// FIXME(b/73383460): The caller, fabricated. This really sucks, but it
-	// is unacceptable to put runtime.Callers() in the hot path.
-	b.writeAll(caller)
-	b.write(']')
-	b.write(' ')
-
-	// User-provided format string, copied.
-	for i := 0; i < len(format); i++ {
-		b.write(format[i])
+	microsecond := int(timestamp.Nanosecond() / 1000)
+
+	// 0 = this frame.
+	// 1 = Debugf, etc.
+	// 2 = Caller.
+	_, file, line, ok := runtime.Caller(2)
+	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
 	}
 
-	// End with a newline.
-	b.write('\n')
+	// Generate the message.
+	message := fmt.Sprintf(format, args...)
 
-	// Pass to the underlying routine.
-	g.Emitter.Emit(level, timestamp, b.String(), 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/glog_unsafe.go b/pkg/log/glog_unsafe.go
deleted file mode 100644
index ea17ae349..000000000
--- a/pkg/log/glog_unsafe.go
+++ /dev/null
@@ -1,32 +0,0 @@
-// 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 (
-	"reflect"
-	"unsafe"
-)
-
-// unsafeString returns a string that points to the given byte array.
-// The byte array must be preserved until the string is disposed.
-func unsafeString(data []byte) (s string) {
-	if len(data) == 0 {
-		return
-	}
-
-	(*reflect.StringHeader)(unsafe.Pointer(&s)).Data = uintptr(unsafe.Pointer(&data[0]))
-	(*reflect.StringHeader)(unsafe.Pointer(&s)).Len = len(data)
-	return
-}
diff --git a/pkg/log/json_k8s.go b/pkg/log/json_k8s.go
index c2c019915..cee6eb514 100644
--- a/pkg/log/json_k8s.go
+++ b/pkg/log/json_k8s.go
@@ -33,7 +33,7 @@ type K8sJSONEmitter struct {
 }
 
 // Emit implements Emitter.Emit.
-func (e K8sJSONEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) {
+func (e *K8sJSONEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) {
 	j := k8sJSONLog{
 		Log:   fmt.Sprintf(format, v...),
 		Level: level,
diff --git a/pkg/log/log.go b/pkg/log/log.go
index 91a81b288..5056f17e6 100644
--- a/pkg/log/log.go
+++ b/pkg/log/log.go
@@ -17,6 +17,18 @@
 // 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 (
@@ -138,8 +150,8 @@ func (l *Writer) Emit(level Level, timestamp time.Time, format string, args ...i
 type MultiEmitter []Emitter
 
 // Emit emits to all emitters.
-func (m MultiEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) {
-	for _, e := range m {
+func (m *MultiEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) {
+	for _, e := range *m {
 		e.Emit(level, timestamp, format, v...)
 	}
 }
@@ -155,7 +167,7 @@ type TestEmitter struct {
 }
 
 // Emit emits to the TestLogger.
-func (t TestEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) {
+func (t *TestEmitter) Emit(level Level, timestamp time.Time, format string, v ...interface{}) {
 	t.Logf(format, v...)
 }
 
@@ -332,5 +344,5 @@ func CopyStandardLogTo(l Level) error {
 
 func init() {
 	// Store the initial value for the log.
-	log.Store(&BasicLogger{Level: Info, Emitter: GoogleEmitter{&Writer{Next: os.Stderr}}})
+	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
index 0634e7c1f..402cc29ae 100644
--- a/pkg/log/log_test.go
+++ b/pkg/log/log_test.go
@@ -16,18 +16,23 @@ 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
 }
@@ -68,3 +73,33 @@ func TestDropMessages(t *testing.T) {
 		}
 	}
 }
+
+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)
+	}
+}