ref/lib/apilog: include the file:line # in the msg, add a unit test
- see the package comment for an explanation of the overlooked
difference between this new package and vlog.LogCall - i.e.
the log header no longer includes the api callsite, rather it
includes the callsite in this package.
Change-Id: Ib3e388f66128ef04e2a31fa72beda64f10c67dae
diff --git a/lib/apilog/log.go b/lib/apilog/apilog.go
similarity index 75%
rename from lib/apilog/log.go
rename to lib/apilog/apilog.go
index 3eb4f92..83c11b0 100644
--- a/lib/apilog/log.go
+++ b/lib/apilog/apilog.go
@@ -2,16 +2,25 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
-// Package apilog provides a function to be used in conjunction with vtrace
-// and logcop automatically injected logging calls. These are called on
-// entry/exit for methods that implements a v23 API call.
+// Package apilog provides functions to be used in conjunction with logcop.
+// In particular, logcop will inject calls to these functions as the first
+// statement in methods that implement the v23 API. The output can
+// be controlled by vlog verbosity or vtrace.
+// The log lines generated have a header that refers to this file
+// and the message includes the file and line # of the caller. This is
+// currently the best we can do given the functionality of the underlying
+// vlog package. It has the advantage the api logging can be selectively
+// enabled/disabled globally using --vmodule=apilog=<level>, but the
+// disadvantage that it can't be controlled at the per file level.
package apilog
import (
"fmt"
"path"
+ "path/filepath"
"reflect"
"runtime"
+ "strconv"
"sync/atomic"
"v.io/x/lib/vlog"
@@ -22,17 +31,23 @@
// logCallLogLevel is the log level beyond which calls are logged.
const logCallLogLevel = 1
-func callerFuncName() string {
+var logger vlog.Logger
+
+func init() {
+ logger = vlog.Log
+}
+
+func callerLocation() string {
var funcName string
const stackSkip = 1
- pc, _, _, ok := runtime.Caller(stackSkip + 1)
+ pc, file, line, ok := runtime.Caller(stackSkip + 1)
if ok {
function := runtime.FuncForPC(pc)
if function != nil {
funcName = path.Base(function.Name())
}
}
- return funcName
+ return filepath.Base(file) + ":" + strconv.Itoa(line) + " " + funcName
}
// TODO(cnicolaou): remove LogCall from vlog.
@@ -89,27 +104,28 @@
// }
//
func LogCall(ctx *context.T, v ...interface{}) func(*context.T, ...interface{}) {
- if !vlog.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
+ if !logger.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
return func(*context.T, ...interface{}) {}
}
- callerFuncName := callerFuncName()
+ callerLocation := callerLocation()
invocationId := newInvocationIdentifier()
var output string
if len(v) > 0 {
- output = fmt.Sprintf("call[%s %s]: args:%v", callerFuncName, invocationId, v)
+ output = fmt.Sprintf("call[%s %s]: args:%v", callerLocation, invocationId, v)
} else {
- output = fmt.Sprintf("call[%s %s]", callerFuncName, invocationId)
+ output = fmt.Sprintf("call[%s %s]", callerLocation, invocationId)
}
- vlog.Info(output)
+ logger.Info(output)
+
// TODO(mattr): annotate vtrace span.
return func(ctx *context.T, v ...interface{}) {
var output string
if len(v) > 0 {
- output = fmt.Sprintf("return[%s %s]: %v", callerFuncName, invocationId, derefSlice(v))
+ output = fmt.Sprintf("return[%s %s]: %v", callerLocation, invocationId, derefSlice(v))
} else {
- output = fmt.Sprintf("return[%s %s]", callerFuncName, invocationId)
+ output = fmt.Sprintf("return[%s %s]", callerLocation, invocationId)
}
- vlog.Info(output)
+ logger.Info(output)
// TODO(mattr): annotate vtrace span.
}
}
@@ -124,17 +140,17 @@
// }
//
func LogCallf(ctx *context.T, format string, v ...interface{}) func(*context.T, string, ...interface{}) {
- if !vlog.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
+ if !logger.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
return func(*context.T, string, ...interface{}) {}
}
- callerFuncName := callerFuncName()
+ callerLocation := callerLocation()
invocationId := newInvocationIdentifier()
- output := fmt.Sprintf("call[%s %s]: %s", callerFuncName, invocationId, fmt.Sprintf(format, v...))
- vlog.Info(output)
+ output := fmt.Sprintf("call[%s %s]: %s", callerLocation, invocationId, fmt.Sprintf(format, v...))
+ logger.Info(output)
// TODO(mattr): annotate vtrace span.
return func(ctx *context.T, format string, v ...interface{}) {
- output := fmt.Sprintf("return[%s %s]: %v", callerFuncName, invocationId, fmt.Sprintf(format, derefSlice(v)...))
- vlog.Info(output)
+ output := fmt.Sprintf("return[%s %s]: %v", callerLocation, invocationId, fmt.Sprintf(format, derefSlice(v)...))
+ logger.Info(output)
// TODO(mattr): annotate vtrace span.
}
}
diff --git a/lib/apilog/apilog_test.go b/lib/apilog/apilog_test.go
new file mode 100644
index 0000000..d085efc
--- /dev/null
+++ b/lib/apilog/apilog_test.go
@@ -0,0 +1,93 @@
+// 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_test
+
+import (
+ "bufio"
+ "io/ioutil"
+ "os"
+ "path/filepath"
+ "regexp"
+ "strings"
+ "testing"
+
+ "v.io/x/lib/vlog"
+
+ "v.io/x/ref/lib/apilog"
+)
+
+func readLogFiles(dir string) ([]string, error) {
+ files, err := ioutil.ReadDir(dir)
+ if err != nil {
+ return nil, err
+ }
+ var contents []string
+ for _, fi := range files {
+ // Skip symlinks to avoid double-counting log lines.
+ if !fi.Mode().IsRegular() {
+ continue
+ }
+ file, err := os.Open(filepath.Join(dir, fi.Name()))
+ if err != nil {
+ return nil, err
+ }
+ scanner := bufio.NewScanner(file)
+ for scanner.Scan() {
+ if line := scanner.Text(); len(line) > 0 && line[0] == 'I' {
+ contents = append(contents, line)
+ }
+ }
+ }
+ return contents, nil
+}
+
+func myLoggedFunc() {
+ f := apilog.LogCall(nil, "entry")
+ f(nil, "exit")
+}
+
+func TestLogCall(t *testing.T) {
+ dir, err := ioutil.TempDir("", "logtest")
+ defer os.RemoveAll(dir)
+ 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)
+ if err != nil {
+ t.Fatalf("unexpected error: %s", err)
+ }
+ if want, got := 2, len(contents); want != got {
+ t.Errorf("Expected %d info lines, got %d instead", want, got)
+ }
+ logCallLineRE := regexp.MustCompile(`\S+ \S+ \S+ ([^:]*):.*(call|return)\[(\S*) (\S*)`)
+ for _, line := range contents {
+ match := logCallLineRE.FindStringSubmatch(line)
+ if len(match) != 5 {
+ t.Errorf("failed to match %s", line)
+ continue
+ }
+ fileName, callType, location, funcName := match[1], match[2], match[3], match[4]
+ if fileName != "apilog.go" {
+ t.Errorf("unexpected file name: %s", fileName)
+ continue
+ }
+ if callType != "call" && callType != "return" {
+ t.Errorf("unexpected call type: %s", callType)
+ }
+ if !strings.HasPrefix(location, "apilog_test.go:") {
+ t.Errorf("unexpected location: %s", location)
+ }
+ if funcName != "apilog_test.myLoggedFunc" {
+ t.Errorf("unexpected func name: %s", funcName)
+ }
+ }
+}
diff --git a/lib/apilog/util_test.go b/lib/apilog/util_test.go
new file mode 100644
index 0000000..9d2ea7d
--- /dev/null
+++ b/lib/apilog/util_test.go
@@ -0,0 +1,15 @@
+// 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/x/lib/vlog"
+
+func SetLog(l vlog.Logger) {
+ logger = l
+}
+
+func Log() vlog.Logger {
+ return logger
+}
