lib/apilog: use ctx based logging and sundry bug fixes.
- context.T now wraps rather than embeds logging.Logger
to avoid an annoying go'ism, namely if a struct
with an embedded struct/interface is converted to
an interface then a 'autogenerated' call frame is
inserted in order to create the interface instance. This
messes up the 'InfoDepth' usage.
- logger.Manager needs to test for context.T and extract its
underlying implementation in order to work correctly.
This was the root cause of the bug fixed by: v.io/c/12543
- expand the unit tests to hopefully catch any regressions.
MultiPart: 1/2
Change-Id: I76b1723d31d394be481b4c2947838a1a5096df73
diff --git a/internal/logger/logger.go b/internal/logger/logger.go
index 22749a2..4f07b0d 100644
--- a/internal/logger/logger.go
+++ b/internal/logger/logger.go
@@ -10,6 +10,7 @@
import (
"v.io/x/lib/vlog"
+ "v.io/v23/context"
"v.io/v23/logging"
)
@@ -53,7 +54,7 @@
func (*dummy) ConfigureFromFlags() error { return nil }
func (*dummy) ExplicitlySetFlags() map[string]string { return nil }
-// Manager determines if the supplied logger implements ManageLog and if so
+// Manager determines if the supplied logging.Logger implements ManageLog and if so
// returns an instance of it. If it doesn't implement ManageLog then Manager
// will return a dummy implementation that is essentially a no-op. It is
// always safe to use it as: logger.Manager(logger.Global()).LogDir() for example.
@@ -61,5 +62,13 @@
if vl, ok := logger.(ManageLog); ok {
return vl
}
+ // If the logger is a context.T then ask it for its implementation
+ // of logging.Logger and look for ManageLog being implemented by it,
+ // since context.T can never implement ManageLog itself.
+ if ctx, ok := logger.(*context.T); ok {
+ if l, ok := ctx.LoggerImplementation().(logging.Logger); ok {
+ return Manager(l)
+ }
+ }
return &dummy{}
}
diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go
index ecfad73..617df60 100644
--- a/internal/logger/logger_test.go
+++ b/internal/logger/logger_test.go
@@ -9,6 +9,7 @@
"v.io/x/lib/vlog"
+ "v.io/v23/context"
"v.io/v23/logging"
"v.io/x/ref/internal/logger"
@@ -28,4 +29,17 @@
// Make sure vlog.Log satisfies the logging interfaces
var _ logger.ManageLog = vlog.Log
var _ logging.Logger = vlog.Log
+
+ // Make sure context.T implements logging.T
+ ctx, _ := context.RootContext()
+ var _ logging.Logger = ctx
+
+ // Make sure that logger.Manager can extract the appropriate management
+ // interface from a context.
+ nl := vlog.NewLogger("test")
+ ctx = context.WithLogger(ctx, nl)
+ manager = logger.Manager(ctx)
+ if _, ok := manager.(*vlog.Logger); !ok {
+ t.Errorf("failed to extract correct manager type")
+ }
}
diff --git a/lib/apilog/apilog.go b/lib/apilog/apilog.go
index 8e76855..a5d3d91 100644
--- a/lib/apilog/apilog.go
+++ b/lib/apilog/apilog.go
@@ -18,21 +18,15 @@
"runtime"
"sync/atomic"
- "v.io/x/lib/vlog"
-
"v.io/v23/context"
"v.io/v23/logging"
+
+ "v.io/x/ref/internal/logger"
)
// logCallLogLevel is the log level beyond which calls are logged.
const logCallLogLevel = 1
-var logger logging.Logger
-
-func init() {
- logger = vlog.Log
-}
-
func callerLocation() string {
var funcName string
const stackSkip = 1
@@ -46,6 +40,13 @@
return funcName
}
+func getLogger(ctx *context.T) logging.Logger {
+ if ctx == nil {
+ return logger.Global()
+ }
+ return ctx
+}
+
// LogCall logs that its caller has been called given the arguments
// passed to it. It returns a function that is supposed to be called
// when the caller returns, logging the caller’s return along with the
@@ -98,7 +99,8 @@
// }
//
func LogCall(ctx *context.T, v ...interface{}) func(*context.T, ...interface{}) {
- if !logger.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
+ l := getLogger(ctx)
+ if !l.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
return func(*context.T, ...interface{}) {}
}
callerLocation := callerLocation()
@@ -109,7 +111,7 @@
} else {
output = fmt.Sprintf("call[%s %s]", callerLocation, invocationId)
}
- logger.InfoDepth(1, output)
+ l.InfoDepth(1, output)
// TODO(mattr): annotate vtrace span.
return func(ctx *context.T, v ...interface{}) {
@@ -119,7 +121,7 @@
} else {
output = fmt.Sprintf("return[%s %s]", callerLocation, invocationId)
}
- logger.InfoDepth(1, output)
+ getLogger(ctx).InfoDepth(1, output)
// TODO(mattr): annotate vtrace span.
}
}
@@ -134,17 +136,18 @@
// }
//
func LogCallf(ctx *context.T, format string, v ...interface{}) func(*context.T, string, ...interface{}) {
- if !logger.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
+ l := getLogger(ctx)
+ if !l.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
return func(*context.T, string, ...interface{}) {}
}
callerLocation := callerLocation()
invocationId := newInvocationIdentifier()
output := fmt.Sprintf("call[%s %s]: %s", callerLocation, invocationId, fmt.Sprintf(format, v...))
- logger.InfoDepth(1, output)
+ l.InfoDepth(1, output)
// TODO(mattr): annotate vtrace span.
return func(ctx *context.T, format string, v ...interface{}) {
output := fmt.Sprintf("return[%s %s]: %v", callerLocation, invocationId, fmt.Sprintf(format, derefSlice(v)...))
- logger.InfoDepth(1, output)
+ getLogger(ctx).InfoDepth(1, output)
// TODO(mattr): annotate vtrace span.
}
}
diff --git a/lib/apilog/apilog_test.go b/lib/apilog/apilog_test.go
index 7debc4c..e440cb1 100644
--- a/lib/apilog/apilog_test.go
+++ b/lib/apilog/apilog_test.go
@@ -14,6 +14,8 @@
"v.io/x/lib/vlog"
+ "v.io/v23/context"
+
"v.io/x/ref/lib/apilog"
)
@@ -42,9 +44,9 @@
return contents, nil
}
-func myLoggedFunc() {
- f := apilog.LogCall(nil, "entry")
- f(nil, "exit")
+func myLoggedFunc(ctx *context.T) {
+ f := apilog.LogCall(ctx, "entry")
+ f(ctx, "exit")
}
func TestLogCall(t *testing.T) {
@@ -53,17 +55,36 @@
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
- logger := vlog.NewLogger("testHeader")
- logger.Configure(vlog.LogDir(dir), vlog.Level(2))
- saveLog := apilog.Log()
- defer func() { apilog.SetLog(saveLog) }()
- apilog.SetLog(logger)
- myLoggedFunc()
- logger.FlushLog()
- contents, err := readLogFiles(dir)
+ l := vlog.NewLogger("testHeader")
+ l.Configure(vlog.LogDir(dir), vlog.Level(2))
+ ctx, _ := context.RootContext()
+ ctx = context.WithLogger(ctx, l)
+ myLoggedFunc(ctx)
+ ctx.FlushLog()
+ testLogOutput(t, dir)
+}
+
+func TestLogCallNoContext(t *testing.T) {
+ dir, err := ioutil.TempDir("", "logtest")
+ defer os.RemoveAll(dir)
if err != nil {
t.Fatalf("unexpected error: %s", err)
}
+ l := vlog.NewLogger("testHeader")
+ l.Configure(vlog.LogDir(dir), vlog.Level(2))
+ saved := vlog.Log
+ vlog.Log = l
+ defer func() { vlog.Log = saved }()
+ myLoggedFunc(nil)
+ vlog.FlushLog()
+ testLogOutput(t, dir)
+}
+
+func testLogOutput(t *testing.T, dir string) {
+ contents, err := readLogFiles(dir)
+ if err != nil {
+ t.Fatalf("unexpected error: %q %s", dir, err)
+ }
if want, got := 2, len(contents); want != got {
t.Errorf("Expected %d info lines, got %d instead", want, got)
}
diff --git a/lib/apilog/util_test.go b/lib/apilog/util_test.go
deleted file mode 100644
index 252ea2a..0000000
--- a/lib/apilog/util_test.go
+++ /dev/null
@@ -1,16 +0,0 @@
-// Copyright 2015 The Vanadium Authors. All rights reserved.
-// Use of this source code is governed by a BSD-style
-// license that can be found in the LICENSE file.
-
-package apilog
-
-import "v.io/v23/logging"
-
-// TODO(cnicolaou): remove these when we are using the context for logging.
-func SetLog(l logging.Logger) {
- logger = l
-}
-
-func Log() logging.Logger {
- return logger
-}
diff --git a/runtime/internal/rpc/test/client_test.go b/runtime/internal/rpc/test/client_test.go
index a42a2a9..bd29251 100644
--- a/runtime/internal/rpc/test/client_test.go
+++ b/runtime/internal/rpc/test/client_test.go
@@ -22,7 +22,9 @@
"v.io/v23/security"
"v.io/v23/vdlroot/signature"
"v.io/v23/verror"
+
"v.io/x/ref"
+ "v.io/x/ref/internal/logger"
_ "v.io/x/ref/runtime/factories/generic"
inaming "v.io/x/ref/runtime/internal/naming"
irpc "v.io/x/ref/runtime/internal/rpc"
@@ -289,6 +291,7 @@
}
emptyCtx := &context.T{}
+ emptyCtx = context.WithLogger(emptyCtx, logger.Global())
_, err := client.StartCall(emptyCtx, "noname", "nomethod", nil)
if verror.ErrorID(err) != verror.ErrBadArg.ID {
t.Fatalf("wrong error: %s", err)
diff --git a/runtime/internal/rt/runtime.go b/runtime/internal/rt/runtime.go
index 6940890..09d1b70 100644
--- a/runtime/internal/rt/runtime.go
+++ b/runtime/internal/rt/runtime.go
@@ -13,6 +13,7 @@
"syscall"
"time"
+ "v.io/x/lib/metadata"
"v.io/x/lib/pubsub"
"v.io/x/lib/vlog"
@@ -112,14 +113,9 @@
// log_dir for the program. It's a hack, but it gets us the metadata
// to device manager-run apps and avoids it for command-lines, which is
// a good enough approximation.
-
- // TODO(caprita): Disabled on 6/11/2015 because changes in the logging
- // system caused this to be always printed. Re-enable in a different
- // way.
-
- // if logger.Manager(ctx).LogDir() != os.TempDir() {
- // ctx.Infof(metadata.ToXML())
- // }
+ if logger.Manager(ctx).LogDir() != os.TempDir() {
+ ctx.Infof(metadata.ToXML())
+ }
// Setup the initial trace.
ctx, err = ivtrace.Init(ctx, flags.Vtrace)
