Move to "github.com/hashicorp/go-hclog" (#4227)

* logbridge with hclog and identical output

* Initial search & replace

This compiles, but there is a fair amount of TODO
and commented out code, especially around the
plugin logclient/logserver code.

* strip logbridge

* fix majority of tests

* update logxi aliases

* WIP fixing tests

* more test fixes

* Update test to hclog

* Fix format

* Rename hclog -> log

* WIP making hclog and logxi love each other

* update logger_test.go

* clean up merged comments

* Replace RawLogger interface with a Logger

* Add some logger names

* Replace Trace with Debug

* update builtin logical logging patterns

* Fix build errors

* More log updates

* update log approach in command and builtin

* More log updates

* update helper, http, and logical directories

* Update loggers

* Log updates

* Update logging

* Update logging

* Update logging

* Update logging

* update logging in physical

* prefixing and lowercase

* Update logging

* Move phyisical logging name to server command

* Fix som tests

* address jims feedback so far

* incorporate brians feedback so far

* strip comments

* move vault.go to logging package

* update Debug to Trace

* Update go-plugin deps

* Update logging based on review comments

* Updates from review

* Unvendor logxi

* Remove null_logger.go

logical/framework/backend.go

@@ -11,11 +11,11 @@ import (
 	"sync"
 	"time"
 
-	log "github.com/mgutz/logxi/v1"
+	log "github.com/hashicorp/go-hclog"
 
 	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/vault/helper/errutil"
-	"github.com/hashicorp/vault/helper/logformat"
+	"github.com/hashicorp/vault/helper/logging"
 	"github.com/hashicorp/vault/helper/parseutil"
 	"github.com/hashicorp/vault/logical"
 )
@@ -255,7 +255,7 @@ func (b *Backend) Logger() log.Logger {
 		return b.logger
 	}
 
-	return logformat.NewVaultLoggerWithWriter(ioutil.Discard, log.LevelOff)
+	return logging.NewVaultLoggerWithWriter(ioutil.Discard, log.NoLevel)
 }
 
 // System returns the backend's system view.

logical/logical.go

@@ -3,7 +3,7 @@ package logical
 import (
 	"context"
 
-	log "github.com/mgutz/logxi/v1"
+	log "github.com/hashicorp/go-hclog"
 )
 
 // BackendType is the type of backend that is being implemented

logical/plugin/backend.go

@@ -7,9 +7,8 @@ import (
 
 	"google.golang.org/grpc"
 
-	hclog "github.com/hashicorp/go-hclog"
+	log "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-plugin"
-	"github.com/hashicorp/vault/helper/logbridge"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/plugin/pb"
 )
@@ -18,12 +17,18 @@ import (
 type BackendPlugin struct {
 	Factory      logical.Factory
 	metadataMode bool
-	Logger       hclog.Logger
+	Logger       log.Logger
 }
 
 // Server gets called when on plugin.Serve()
 func (b *BackendPlugin) Server(broker *plugin.MuxBroker) (interface{}, error) {
-	return &backendPluginServer{factory: b.Factory, broker: broker}, nil
+	return &backendPluginServer{
+		factory: b.Factory,
+		broker:  broker,
+		// We pass the logger down into the backend so go-plugin will forward
+		// logs for us.
+		logger: b.Logger,
+	}, nil
 }
 
 // Client gets called on plugin.NewClient()
@@ -37,7 +42,7 @@ func (b BackendPlugin) GRPCServer(broker *plugin.GRPCBroker, s *grpc.Server) err
 		factory: b.Factory,
 		// We pass the logger down into the backend so go-plugin will forward
 		// logs for us.
-		logger: logbridge.NewLogger(b.Logger).LogxiLogger(),
+		logger: b.Logger,
 	})
 	return nil
 }

logical/plugin/backend_client.go

@@ -5,9 +5,9 @@ import (
 	"errors"
 	"net/rpc"
 
+	log "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-plugin"
 	"github.com/hashicorp/vault/logical"
-	log "github.com/mgutz/logxi/v1"
 )
 
 var (
@@ -204,16 +204,6 @@ func (b *backendPluginClient) Setup(ctx context.Context, config *logical.Backend
 		impl: storageImpl,
 	})
 
-	// Shim log.Logger
-	loggerImpl := config.Logger
-	if b.metadataMode {
-		loggerImpl = log.NullLog
-	}
-	loggerID := b.broker.NextId()
-	go b.broker.AcceptAndServe(loggerID, &LoggerServer{
-		logger: loggerImpl,
-	})
-
 	// Shim logical.SystemView
 	sysViewImpl := config.System
 	if b.metadataMode {
@@ -226,7 +216,6 @@ func (b *backendPluginClient) Setup(ctx context.Context, config *logical.Backend
 
 	args := &SetupArgs{
 		StorageID:   storageID,
-		LoggerID:    loggerID,
 		SysViewID:   sysViewID,
 		Config:      config.Config,
 		BackendUUID: config.BackendUUID,

logical/plugin/backend_server.go

@@ -6,6 +6,8 @@ import (
 	"net/rpc"
 	"os"
 
+	"github.com/hashicorp/go-hclog"
+
 	"github.com/hashicorp/go-plugin"
 	"github.com/hashicorp/vault/helper/pluginutil"
 	"github.com/hashicorp/vault/logical"
@@ -22,7 +24,7 @@ type backendPluginServer struct {
 	backend logical.Backend
 	factory logical.Factory
 
-	loggerClient  *rpc.Client
+	logger        hclog.Logger
 	sysViewClient *rpc.Client
 	storageClient *rpc.Client
 }
@@ -77,7 +79,6 @@ func (b *backendPluginServer) Cleanup(_ interface{}, _ *struct{}) error {
 	b.backend.Cleanup(context.Background())
 
 	// Close rpc clients
-	b.loggerClient.Close()
 	b.sysViewClient.Close()
 	b.storageClient.Close()
 	return nil
@@ -109,19 +110,6 @@ func (b *backendPluginServer) Setup(args *SetupArgs, reply *SetupReply) error {
 
 	storage := &StorageClient{client: rawStorageClient}
 
-	// Dial for logger
-	loggerConn, err := b.broker.Dial(args.LoggerID)
-	if err != nil {
-		*reply = SetupReply{
-			Error: wrapError(err),
-		}
-		return nil
-	}
-	rawLoggerClient := rpc.NewClient(loggerConn)
-	b.loggerClient = rawLoggerClient
-
-	logger := &LoggerClient{client: rawLoggerClient}
-
 	// Dial for sys view
 	sysViewConn, err := b.broker.Dial(args.SysViewID)
 	if err != nil {
@@ -137,7 +125,7 @@ func (b *backendPluginServer) Setup(args *SetupArgs, reply *SetupReply) error {
 
 	config := &logical.BackendConfig{
 		StorageView: storage,
-		Logger:      logger,
+		Logger:      b.logger,
 		System:      sysView,
 		Config:      args.Config,
 		BackendUUID: args.BackendUUID,

logical/plugin/backend_test.go

@@ -5,11 +5,11 @@ import (
 	"testing"
 	"time"
 
+	log "github.com/hashicorp/go-hclog"
 	gplugin "github.com/hashicorp/go-plugin"
-	"github.com/hashicorp/vault/helper/logformat"
+	"github.com/hashicorp/vault/helper/logging"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/plugin/mock"
-	log "github.com/mgutz/logxi/v1"
 )
 
 func TestBackendPlugin_impl(t *testing.T) {
@@ -156,7 +156,7 @@ func testBackend(t *testing.T) (logical.Backend, func()) {
 	b := raw.(logical.Backend)
 
 	err = b.Setup(context.Background(), &logical.BackendConfig{
-		Logger: logformat.NewVaultLogger(log.LevelTrace),
+		Logger: logging.NewVaultLogger(log.Debug),
 		System: &logical.StaticSystemView{
 			DefaultLeaseTTLVal: 300 * time.Second,
 			MaxLeaseTTLVal:     1800 * time.Second,

logical/plugin/grpc_backend_client.go

@@ -7,11 +7,11 @@ import (
 
 	"google.golang.org/grpc"
 
+	log "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-plugin"
 	"github.com/hashicorp/vault/helper/pluginutil"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/plugin/pb"
-	log "github.com/mgutz/logxi/v1"
 )
 
 var ErrPluginShutdown = errors.New("plugin is shut down")

logical/plugin/grpc_backend_server.go

@@ -3,10 +3,10 @@ package plugin
 import (
 	"context"
 
+	log "github.com/hashicorp/go-hclog"
 	plugin "github.com/hashicorp/go-plugin"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/plugin/pb"
-	log "github.com/mgutz/logxi/v1"
 	"google.golang.org/grpc"
 )
 

logical/plugin/grpc_backend_test.go

@@ -6,12 +6,11 @@ import (
 	"testing"
 	"time"
 
-	hclog "github.com/hashicorp/go-hclog"
+	log "github.com/hashicorp/go-hclog"
 	gplugin "github.com/hashicorp/go-plugin"
-	"github.com/hashicorp/vault/helper/logformat"
+	"github.com/hashicorp/vault/helper/logging"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/plugin/mock"
-	log "github.com/mgutz/logxi/v1"
 )
 
 func TestGRPCBackendPlugin_impl(t *testing.T) {
@@ -143,8 +142,8 @@ func testGRPCBackend(t *testing.T) (logical.Backend, func()) {
 	pluginMap := map[string]gplugin.Plugin{
 		"backend": &BackendPlugin{
 			Factory: mock.Factory,
-			Logger: hclog.New(&hclog.LoggerOptions{
-				Level:      hclog.Trace,
+			Logger: log.New(&log.LoggerOptions{
+				Level:      log.Debug,
 				Output:     os.Stderr,
 				JSONFormat: true,
 			}),
@@ -163,7 +162,7 @@ func testGRPCBackend(t *testing.T) (logical.Backend, func()) {
 	b := raw.(logical.Backend)
 
 	err = b.Setup(context.Background(), &logical.BackendConfig{
-		Logger: logformat.NewVaultLogger(log.LevelTrace),
+		Logger: logging.NewVaultLogger(log.Debug),
 		System: &logical.StaticSystemView{
 			DefaultLeaseTTLVal: 300 * time.Second,
 			MaxLeaseTTLVal:     1800 * time.Second,

logical/plugin/logger.go

@@ -1,114 +1,9 @@
 package plugin
 
-import (
-	"net/rpc"
-
-	log "github.com/mgutz/logxi/v1"
-)
-
-type LoggerClient struct {
-	client *rpc.Client
-}
-
-func (l *LoggerClient) Trace(msg string, args ...interface{}) {
-	cArgs := &LoggerArgs{
-		Msg:  msg,
-		Args: args,
-	}
-	l.client.Call("Plugin.Trace", cArgs, &struct{}{})
-}
-
-func (l *LoggerClient) Debug(msg string, args ...interface{}) {
-	cArgs := &LoggerArgs{
-		Msg:  msg,
-		Args: args,
-	}
-	l.client.Call("Plugin.Debug", cArgs, &struct{}{})
-}
-
-func (l *LoggerClient) Info(msg string, args ...interface{}) {
-	cArgs := &LoggerArgs{
-		Msg:  msg,
-		Args: args,
-	}
-	l.client.Call("Plugin.Info", cArgs, &struct{}{})
-}
-func (l *LoggerClient) Warn(msg string, args ...interface{}) error {
-	var reply LoggerReply
-	cArgs := &LoggerArgs{
-		Msg:  msg,
-		Args: args,
-	}
-	err := l.client.Call("Plugin.Warn", cArgs, &reply)
-	if err != nil {
-		return err
-	}
-	if reply.Error != nil {
-		return reply.Error
-	}
-
-	return nil
-}
-func (l *LoggerClient) Error(msg string, args ...interface{}) error {
-	var reply LoggerReply
-	cArgs := &LoggerArgs{
-		Msg:  msg,
-		Args: args,
-	}
-	err := l.client.Call("Plugin.Error", cArgs, &reply)
-	if err != nil {
-		return err
-	}
-	if reply.Error != nil {
-		return reply.Error
-	}
-
-	return nil
-}
-
-func (l *LoggerClient) Fatal(msg string, args ...interface{}) {
-	// NOOP since it's not actually used within vault
-	return
-}
-
-func (l *LoggerClient) Log(level int, msg string, args []interface{}) {
-	cArgs := &LoggerArgs{
-		Level: level,
-		Msg:   msg,
-		Args:  args,
-	}
-	l.client.Call("Plugin.Log", cArgs, &struct{}{})
-}
-
-func (l *LoggerClient) SetLevel(level int) {
-	l.client.Call("Plugin.SetLevel", level, &struct{}{})
-}
-
-func (l *LoggerClient) IsTrace() bool {
-	var reply LoggerReply
-	l.client.Call("Plugin.IsTrace", new(interface{}), &reply)
-	return reply.IsTrue
-}
-func (l *LoggerClient) IsDebug() bool {
-	var reply LoggerReply
-	l.client.Call("Plugin.IsDebug", new(interface{}), &reply)
-	return reply.IsTrue
-}
-
-func (l *LoggerClient) IsInfo() bool {
-	var reply LoggerReply
-	l.client.Call("Plugin.IsInfo", new(interface{}), &reply)
-	return reply.IsTrue
-}
-
-func (l *LoggerClient) IsWarn() bool {
-	var reply LoggerReply
-	l.client.Call("Plugin.IsWarn", new(interface{}), &reply)
-	return reply.IsTrue
-}
+import hclog "github.com/hashicorp/go-hclog"
 
 type LoggerServer struct {
-	logger log.Logger
+	logger hclog.Logger
 }
 
 func (l *LoggerServer) Trace(args *LoggerArgs, _ *struct{}) error {
@@ -127,34 +22,42 @@ func (l *LoggerServer) Info(args *LoggerArgs, _ *struct{}) error {
 }
 
 func (l *LoggerServer) Warn(args *LoggerArgs, reply *LoggerReply) error {
-	err := l.logger.Warn(args.Msg, args.Args...)
-	if err != nil {
-		*reply = LoggerReply{
-			Error: wrapError(err),
-		}
-		return nil
-	}
+	l.logger.Warn(args.Msg, args.Args...)
 	return nil
 }
 
 func (l *LoggerServer) Error(args *LoggerArgs, reply *LoggerReply) error {
-	err := l.logger.Error(args.Msg, args.Args...)
-	if err != nil {
-		*reply = LoggerReply{
-			Error: wrapError(err),
-		}
-		return nil
-	}
+	l.logger.Error(args.Msg, args.Args...)
 	return nil
 }
 
 func (l *LoggerServer) Log(args *LoggerArgs, _ *struct{}) error {
-	l.logger.Log(args.Level, args.Msg, args.Args)
+
+	switch translateLevel(args.Level) {
+
+	case hclog.Trace:
+		l.logger.Trace(args.Msg, args.Args...)
+
+	case hclog.Debug:
+		l.logger.Debug(args.Msg, args.Args...)
+
+	case hclog.Info:
+		l.logger.Info(args.Msg, args.Args...)
+
+	case hclog.Warn:
+		l.logger.Warn(args.Msg, args.Args...)
+
+	case hclog.Error:
+		l.logger.Error(args.Msg, args.Args...)
+
+	case hclog.NoLevel:
+	}
 	return nil
 }
 
 func (l *LoggerServer) SetLevel(args int, _ *struct{}) error {
-	l.logger.SetLevel(args)
+	level := translateLevel(args)
+	l.logger = hclog.New(&hclog.LoggerOptions{Level: level})
 	return nil
 }
 
@@ -202,3 +105,30 @@ type LoggerReply struct {
 	IsTrue bool
 	Error  error
 }
+
+func translateLevel(logxiLevel int) hclog.Level {
+
+	switch logxiLevel {
+
+	case 1000, 10:
+		// logxi.LevelAll, logxi.LevelTrace:
+		return hclog.Trace
+
+	case 7:
+		// logxi.LevelDebug:
+		return hclog.Debug
+
+	case 6, 5:
+		// logxi.LevelInfo, logxi.LevelNotice:
+		return hclog.Info
+
+	case 4:
+		// logxi.LevelWarn:
+		return hclog.Warn
+
+	case 3, 2, 1, -1:
+		// logxi.LevelError, logxi.LevelFatal, logxi.LevelAlert, logxi.LevelEmergency:
+		return hclog.Error
+	}
+	return hclog.NoLevel
+}

logical/plugin/logger_test.go

@@ -4,17 +4,15 @@ import (
 	"bufio"
 	"bytes"
 	"io/ioutil"
+	"net/rpc"
 	"strings"
 	"testing"
 
-	plugin "github.com/hashicorp/go-plugin"
-	"github.com/hashicorp/vault/helper/logformat"
-	log "github.com/mgutz/logxi/v1"
-)
+	"github.com/hashicorp/go-hclog"
 
-func TestLogger_impl(t *testing.T) {
-	var _ log.Logger = new(LoggerClient)
-}
+	plugin "github.com/hashicorp/go-plugin"
+	"github.com/hashicorp/vault/helper/logging"
+)
 
 func TestLogger_levels(t *testing.T) {
 	client, server := plugin.TestRPCConn(t)
@@ -23,14 +21,14 @@ func TestLogger_levels(t *testing.T) {
 	var buf bytes.Buffer
 	writer := bufio.NewWriter(&buf)
 
-	l := logformat.NewVaultLoggerWithWriter(writer, log.LevelTrace)
+	l := logging.NewVaultLoggerWithWriter(writer, hclog.Trace)
 
 	server.RegisterName("Plugin", &LoggerServer{
 		logger: l,
 	})
 
 	expected := "foobar"
-	testLogger := &LoggerClient{client: client}
+	testLogger := &deprecatedLoggerClient{client: client}
 
 	// Test trace
 	testLogger.Trace(expected)
@@ -103,13 +101,13 @@ func TestLogger_isLevels(t *testing.T) {
 	client, server := plugin.TestRPCConn(t)
 	defer client.Close()
 
-	l := logformat.NewVaultLoggerWithWriter(ioutil.Discard, log.LevelAll)
+	l := logging.NewVaultLoggerWithWriter(ioutil.Discard, hclog.Trace)
 
 	server.RegisterName("Plugin", &LoggerServer{
 		logger: l,
 	})
 
-	testLogger := &LoggerClient{client: client}
+	testLogger := &deprecatedLoggerClient{client: client}
 
 	if !testLogger.IsDebug() || !testLogger.IsInfo() || !testLogger.IsTrace() || !testLogger.IsWarn() {
 		t.Fatal("expected logger to return true for all logger level checks")
@@ -123,17 +121,17 @@ func TestLogger_log(t *testing.T) {
 	var buf bytes.Buffer
 	writer := bufio.NewWriter(&buf)
 
-	l := logformat.NewVaultLoggerWithWriter(writer, log.LevelTrace)
+	l := logging.NewVaultLoggerWithWriter(writer, hclog.Trace)
 
 	server.RegisterName("Plugin", &LoggerServer{
 		logger: l,
 	})
 
 	expected := "foobar"
-	testLogger := &LoggerClient{client: client}
+	testLogger := &deprecatedLoggerClient{client: client}
 
-	// Test trace
-	testLogger.Log(log.LevelInfo, expected, nil)
+	// Test trace 6 = logxi.LevelInfo
+	testLogger.Log(6, expected, nil)
 	if err := writer.Flush(); err != nil {
 		t.Fatal(err)
 	}
@@ -148,16 +146,117 @@ func TestLogger_setLevel(t *testing.T) {
 	client, server := plugin.TestRPCConn(t)
 	defer client.Close()
 
-	l := log.NewLogger(ioutil.Discard, "test-logger")
+	l := hclog.New(&hclog.LoggerOptions{Output: ioutil.Discard})
 
 	server.RegisterName("Plugin", &LoggerServer{
 		logger: l,
 	})
 
-	testLogger := &LoggerClient{client: client}
-	testLogger.SetLevel(log.LevelWarn)
+	testLogger := &deprecatedLoggerClient{client: client}
+	testLogger.SetLevel(4) // 4 == logxi.LevelWarn
 
 	if !testLogger.IsWarn() {
 		t.Fatal("expected logger to support warn level")
 	}
 }
+
+type deprecatedLoggerClient struct {
+	client *rpc.Client
+}
+
+func (l *deprecatedLoggerClient) Trace(msg string, args ...interface{}) {
+	cArgs := &LoggerArgs{
+		Msg:  msg,
+		Args: args,
+	}
+	l.client.Call("Plugin.Trace", cArgs, &struct{}{})
+}
+
+func (l *deprecatedLoggerClient) Debug(msg string, args ...interface{}) {
+	cArgs := &LoggerArgs{
+		Msg:  msg,
+		Args: args,
+	}
+	l.client.Call("Plugin.Debug", cArgs, &struct{}{})
+}
+
+func (l *deprecatedLoggerClient) Info(msg string, args ...interface{}) {
+	cArgs := &LoggerArgs{
+		Msg:  msg,
+		Args: args,
+	}
+	l.client.Call("Plugin.Info", cArgs, &struct{}{})
+}
+func (l *deprecatedLoggerClient) Warn(msg string, args ...interface{}) error {
+	var reply LoggerReply
+	cArgs := &LoggerArgs{
+		Msg:  msg,
+		Args: args,
+	}
+	err := l.client.Call("Plugin.Warn", cArgs, &reply)
+	if err != nil {
+		return err
+	}
+	if reply.Error != nil {
+		return reply.Error
+	}
+
+	return nil
+}
+func (l *deprecatedLoggerClient) Error(msg string, args ...interface{}) error {
+	var reply LoggerReply
+	cArgs := &LoggerArgs{
+		Msg:  msg,
+		Args: args,
+	}
+	err := l.client.Call("Plugin.Error", cArgs, &reply)
+	if err != nil {
+		return err
+	}
+	if reply.Error != nil {
+		return reply.Error
+	}
+
+	return nil
+}
+
+func (l *deprecatedLoggerClient) Fatal(msg string, args ...interface{}) {
+	// NOOP since it's not actually used within vault
+	return
+}
+
+func (l *deprecatedLoggerClient) Log(level int, msg string, args []interface{}) {
+	cArgs := &LoggerArgs{
+		Level: level,
+		Msg:   msg,
+		Args:  args,
+	}
+	l.client.Call("Plugin.Log", cArgs, &struct{}{})
+}
+
+func (l *deprecatedLoggerClient) SetLevel(level int) {
+	l.client.Call("Plugin.SetLevel", level, &struct{}{})
+}
+
+func (l *deprecatedLoggerClient) IsTrace() bool {
+	var reply LoggerReply
+	l.client.Call("Plugin.IsTrace", new(interface{}), &reply)
+	return reply.IsTrue
+}
+func (l *deprecatedLoggerClient) IsDebug() bool {
+	var reply LoggerReply
+	l.client.Call("Plugin.IsDebug", new(interface{}), &reply)
+	return reply.IsTrue
+}
+
+func (l *deprecatedLoggerClient) IsInfo() bool {
+	var reply LoggerReply
+	l.client.Call("Plugin.IsInfo", new(interface{}), &reply)
+	return reply.IsTrue
+}
+
+func (l *deprecatedLoggerClient) IsWarn() bool {
+	var reply LoggerReply
+	l.client.Call("Plugin.IsWarn", new(interface{}), &reply)
+	return reply.IsTrue
+}

logical/plugin/middleware.go

@@ -4,16 +4,14 @@ import (
 	"context"
 	"time"
 
+	log "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault/logical"
-	log "github.com/mgutz/logxi/v1"
 )
 
 // backendPluginClient implements logical.Backend and is the
 // go-plugin client.
 type backendTracingMiddleware struct {
-	logger    log.Logger
-	transport string
-	typeStr   string
+	logger log.Logger
 
 	next logical.Backend
 }
@@ -23,19 +21,19 @@ var _ logical.Backend = &backendTracingMiddleware{}
 
 func (b *backendTracingMiddleware) HandleRequest(ctx context.Context, req *logical.Request) (resp *logical.Response, err error) {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.HandleRequest", "path", req.Path, "status", "finished", "type", b.typeStr, "transport", b.transport, "err", err, "took", time.Since(then))
+		b.logger.Trace("handle request", "path", req.Path, "status", "finished", "err", err, "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.HandleRequest", "path", req.Path, "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("handle request", "path", req.Path, "status", "started")
 	return b.next.HandleRequest(ctx, req)
 }
 
 func (b *backendTracingMiddleware) SpecialPaths() *logical.Paths {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.SpecialPaths", "status", "finished", "type", b.typeStr, "transport", b.transport, "took", time.Since(then))
+		b.logger.Trace("special paths", "status", "finished", "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.SpecialPaths", "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("special paths", "status", "started")
 	return b.next.SpecialPaths()
 }
 
@@ -49,45 +47,45 @@ func (b *backendTracingMiddleware) Logger() log.Logger {
 
 func (b *backendTracingMiddleware) HandleExistenceCheck(ctx context.Context, req *logical.Request) (found bool, exists bool, err error) {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.HandleExistenceCheck", "path", req.Path, "status", "finished", "type", b.typeStr, "transport", b.transport, "err", err, "took", time.Since(then))
+		b.logger.Trace("handle existence check", "path", req.Path, "status", "finished", "err", err, "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.HandleExistenceCheck", "path", req.Path, "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("handle existence check", "path", req.Path, "status", "started")
 	return b.next.HandleExistenceCheck(ctx, req)
 }
 
 func (b *backendTracingMiddleware) Cleanup(ctx context.Context) {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.Cleanup", "status", "finished", "type", b.typeStr, "transport", b.transport, "took", time.Since(then))
+		b.logger.Trace("cleanup", "status", "finished", "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.Cleanup", "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("cleanup", "status", "started")
 	b.next.Cleanup(ctx)
 }
 
 func (b *backendTracingMiddleware) InvalidateKey(ctx context.Context, key string) {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.InvalidateKey", "key", key, "status", "finished", "type", b.typeStr, "transport", b.transport, "took", time.Since(then))
+		b.logger.Trace("invalidate key", "key", key, "status", "finished", "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.InvalidateKey", "key", key, "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("invalidate key", "key", key, "status", "started")
 	b.next.InvalidateKey(ctx, key)
 }
 
 func (b *backendTracingMiddleware) Setup(ctx context.Context, config *logical.BackendConfig) (err error) {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.Setup", "status", "finished", "type", b.typeStr, "transport", b.transport, "err", err, "took", time.Since(then))
+		b.logger.Trace("setup", "status", "finished", "err", err, "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.Setup", "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("setup", "status", "started")
 	return b.next.Setup(ctx, config)
 }
 
 func (b *backendTracingMiddleware) Type() logical.BackendType {
 	defer func(then time.Time) {
-		b.logger.Trace("plugin.Type", "status", "finished", "type", b.typeStr, "transport", b.transport, "took", time.Since(then))
+		b.logger.Trace("type", "status", "finished", "took", time.Since(then))
 	}(time.Now())
 
-	b.logger.Trace("plugin.Type", "status", "started", "type", b.typeStr, "transport", b.transport)
+	b.logger.Trace("type", "status", "started")
 	return b.next.Type()
 }

logical/plugin/plugin.go

@@ -11,10 +11,10 @@ import (
 
 	"sync"
 
+	log "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-plugin"
 	"github.com/hashicorp/vault/helper/pluginutil"
 	"github.com/hashicorp/vault/logical"
-	log "github.com/mgutz/logxi/v1"
 )
 
 // init registers basic structs with gob which will be used to transport complex
@@ -101,12 +101,14 @@ func newPluginClient(ctx context.Context, sys pluginutil.RunnerUtil, pluginRunne
 		},
 	}
 
+	namedLogger := logger.Named(pluginRunner.Name)
+
 	var client *plugin.Client
 	var err error
 	if isMetadataMode {
-		client, err = pluginRunner.RunMetadataMode(ctx, sys, pluginMap, handshakeConfig, []string{}, logger)
+		client, err = pluginRunner.RunMetadataMode(ctx, sys, pluginMap, handshakeConfig, []string{}, namedLogger)
 	} else {
-		client, err = pluginRunner.Run(ctx, sys, pluginMap, handshakeConfig, []string{}, logger)
+		client, err = pluginRunner.Run(ctx, sys, pluginMap, handshakeConfig, []string{}, namedLogger)
 	}
 	if err != nil {
 		return nil, err
@@ -140,12 +142,10 @@ func newPluginClient(ctx context.Context, sys pluginutil.RunnerUtil, pluginRunne
 	}
 
 	// Wrap the backend in a tracing middleware
-	if logger.IsTrace() {
+	if namedLogger.IsTrace() {
 		backend = &backendTracingMiddleware{
-			logger:    logger,
-			transport: transport,
-			typeStr:   pluginRunner.Name,
-			next:      backend,
+			logger: namedLogger.With("transport", transport),
+			next:   backend,
 		}
 	}
 

logical/plugin/serve.go

@@ -4,7 +4,7 @@ import (
 	"crypto/tls"
 	"os"
 
-	hclog "github.com/hashicorp/go-hclog"
+	log "github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-plugin"
 	"github.com/hashicorp/vault/helper/pluginutil"
 	"github.com/hashicorp/vault/logical"
@@ -19,7 +19,7 @@ type TLSProviderFunc func() (*tls.Config, error)
 type ServeOpts struct {
 	BackendFactoryFunc logical.Factory
 	TLSProviderFunc    TLSProviderFunc
-	Logger             hclog.Logger
+	Logger             log.Logger
 }
 
 // Serve is a helper function used to serve a backend plugin. This
@@ -27,8 +27,8 @@ type ServeOpts struct {
 func Serve(opts *ServeOpts) error {
 	logger := opts.Logger
 	if logger == nil {
-		logger = hclog.New(&hclog.LoggerOptions{
-			Level:      hclog.Trace,
+		logger = log.New(&log.LoggerOptions{
+			Level:      log.Trace,
 			Output:     os.Stderr,
 			JSONFormat: true,
 		})

logical/testing.go

@@ -6,8 +6,8 @@ import (
 	"testing"
 	"time"
 
-	"github.com/hashicorp/vault/helper/logformat"
-	log "github.com/mgutz/logxi/v1"
+	log "github.com/hashicorp/go-hclog"
+	"github.com/hashicorp/vault/helper/logging"
 )
 
 // TestRequest is a helper to create a purely in-memory Request struct.
@@ -76,10 +76,9 @@ func TestSystemView() *StaticSystemView {
 
 func TestBackendConfig() *BackendConfig {
 	bc := &BackendConfig{
-		Logger: logformat.NewVaultLogger(log.LevelTrace),
+		Logger: logging.NewVaultLogger(log.Trace),
 		System: TestSystemView(),
 	}
-	bc.Logger.SetLevel(log.LevelTrace)
 
 	return bc
 }

logical/testing/testing.go

@@ -9,11 +9,11 @@ import (
 	"sort"
 	"testing"
 
-	log "github.com/mgutz/logxi/v1"
+	log "github.com/hashicorp/go-hclog"
 
 	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/vault/api"
-	"github.com/hashicorp/vault/helper/logformat"
+	"github.com/hashicorp/vault/helper/logging"
 	"github.com/hashicorp/vault/http"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/physical/inmem"
@@ -135,7 +135,7 @@ func Test(tt TestT, c TestCase) {
 	}
 
 	// Create an in-memory Vault core
-	logger := logformat.NewVaultLogger(log.LevelTrace)
+	logger := logging.NewVaultLogger(log.Trace)
 
 	phys, err := inmem.NewInmem(nil, logger)
 	if err != nil {
@@ -210,8 +210,8 @@ func Test(tt TestT, c TestCase) {
 	// Make requests
 	var revoke []*logical.Request
 	for i, s := range c.Steps {
-		if log.IsWarn() {
-			log.Warn("Executing test step", "step_number", i+1)
+		if logger.IsWarn() {
+			logger.Warn("Executing test step", "step_number", i+1)
 		}
 
 		// Create the request
@@ -294,8 +294,8 @@ func Test(tt TestT, c TestCase) {
 	// Revoke any secrets we might have.
 	var failedRevokes []*logical.Secret
 	for _, req := range revoke {
-		if log.IsWarn() {
-			log.Warn("Revoking secret", "secret", fmt.Sprintf("%#v", req))
+		if logger.IsWarn() {
+			logger.Warn("Revoking secret", "secret", fmt.Sprintf("%#v", req))
 		}
 		req.ClientToken = client.Token()
 		resp, err := core.HandleRequest(req)
@@ -311,7 +311,7 @@ func Test(tt TestT, c TestCase) {
 	// Perform any rollbacks. This should no-op if there aren't any.
 	// We set the "immediate" flag here that any backend can pick up on
 	// to do all rollbacks immediately even if the WAL entries are new.
-	log.Warn("Requesting RollbackOperation")
+	logger.Warn("Requesting RollbackOperation")
 	req := logical.RollbackRequest(prefix + "/")
 	req.Data["immediate"] = true
 	req.ClientToken = client.Token()