lib/apilog/apilog.go

// 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 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.
// --vmodule=apilog=<level> can be used to globally control logging,
// and --vmodule=module=<level> can also be used to control logging
// on a per-file basis.
package apilog

import (
	"fmt"
	"path"
	"reflect"
	"runtime"
	"sync/atomic"

	"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

func callerLocation() string {
	var funcName string
	const stackSkip = 1
	pc, _, _, ok := runtime.Caller(stackSkip + 1)
	if ok {
		function := runtime.FuncForPC(pc)
		if function != nil {
			funcName = path.Base(function.Name())
		}
	}
	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
// arguments it is provided with.
// File name and line number of the call site and a randomly generated
// invocation identifier is logged automatically.  The path through which
// the caller function returns will be logged automatically too.
//
// The canonical way to use LogCall is along the lines of the following:
//
//     func Function(ctx *context.T, a Type1, b Type2) ReturnType {
//         defer apilog.LogCall(ctx, a, b)(ctx)
//         // ... function body ...
//         return retVal
//     }
//
// To log the return value as the function returns, the following
// pattern should be used. Note that pointers to the output
// variables should be passed to the returning function, not the
// variables themselves. Also note that nil can be used when a context.T
// is not available:
//
//     func Function(a Type1, b Type2) (r ReturnType) {
//         defer apilog.LogCall(nil, a, b)(nil, &r)
//         // ... function body ...
//         return computeReturnValue()
//     }
//
// Note that when using this pattern, you do not need to actually
// assign anything to the named return variable explicitly.  A regular
// return statement would automatically do the proper return variable
// assignments.
//
// The log injector tool will automatically insert a LogCall invocation
// into all implementations of the public API it runs, unless a Valid
// Log Construct is found.  A Valid Log Construct is defined as one of
// the following at the beginning of the function body (i.e. should not
// be preceded by any non-whitespace or non-comment tokens):
//     1. defer apilog.LogCall(optional arguments)(optional pointers to return values)
//     2. defer apilog.LogCallf(argsFormat, optional arguments)(returnValuesFormat, optional pointers to return values)
//     3. // nologcall
//
// The comment "// nologcall" serves as a hint to log injection and
// checking tools to exclude the function from their consideration.
// It is used as follows:
//
//     func FunctionWithoutLogging(args ...interface{}) {
//         // nologcall
//         // ... function body ...
//     }
//
func LogCall(ctx *context.T, v ...interface{}) func(*context.T, ...interface{}) {
	l := getLogger(ctx)
	if !l.V(logCallLogLevel) { // TODO(mattr): add call to vtrace.
		return func(*context.T, ...interface{}) {}
	}
	callerLocation := callerLocation()
	invocationId := newInvocationIdentifier()
	var output string
	if len(v) > 0 {
		output = fmt.Sprintf("call[%s %s]: args:%v", callerLocation, invocationId, v)
	} else {
		output = fmt.Sprintf("call[%s %s]", callerLocation, invocationId)
	}
	l.InfoDepth(1, 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", callerLocation, invocationId, derefSlice(v))
		} else {
			output = fmt.Sprintf("return[%s %s]", callerLocation, invocationId)
		}
		getLogger(ctx).InfoDepth(1, output)
		// TODO(mattr): annotate vtrace span.
	}
}

// LogCallf behaves identically to LogCall, except it lets the caller to
// customize the log messages via format specifiers, like the following:
//
//     func Function(a Type1, b Type2) (r, t ReturnType) {
//         defer apilog.LogCallf(nil, "a: %v, b: %v", a, b)(nil, "(r,t)=(%v,%v)", &r, &t)
//         // ... function body ...
//         return finalR, finalT
//     }
//
func LogCallf(ctx *context.T, format string, v ...interface{}) func(*context.T, string, ...interface{}) {
	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...))
	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)...))
		getLogger(ctx).InfoDepth(1, output)
		// TODO(mattr): annotate vtrace span.
	}
}

func derefSlice(slice []interface{}) []interface{} {
	o := make([]interface{}, 0, len(slice))
	for _, x := range slice {
		o = append(o, reflect.Indirect(reflect.ValueOf(x)).Interface())
	}
	return o
}

var invocationCounter uint64 = 0

// newInvocationIdentifier generates a unique identifier for a method invocation
// to make it easier to match up log lines for the entry and exit of a function
// when looking at a log transcript.
func newInvocationIdentifier() string {
	const (
		charSet    = "ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789abcdefghijklmnopqrstuvwxyz"
		charSetLen = uint64(len(charSet))
	)
	r := []byte{'@'}
	for n := atomic.AddUint64(&invocationCounter, 1); n > 0; n /= charSetLen {
		r = append(r, charSet[n%charSetLen])
	}
	return string(r)
}