Merge pull request #1755 from hashicorp/logxi

Convert to logxi

builtin/credential/approle/path_tidy_user_id.go

@@ -5,7 +5,6 @@ import (
 	"sync/atomic"
 	"time"
 
-	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/framework"
@@ -59,7 +58,7 @@ func (b *backend) tidySecretID(s logical.Storage) error {
 			}
 
 			if secretIDEntry == nil {
-				result = multierror.Append(result, errwrap.Wrapf("[ERR] {{err}}", fmt.Errorf("entry for SecretID %s is nil", secretIDHMAC)))
+				result = multierror.Append(result, fmt.Errorf("entry for SecretID %s is nil", secretIDHMAC))
 				lock.Unlock()
 				continue
 			}

builtin/credential/cert/path_login.go

@@ -218,18 +218,18 @@ func (b *backend) loadTrustedCerts(store logical.Storage) (pool *x509.CertPool,
 	trustedNonCAs = make([]*ParsedCert, 0)
 	names, err := store.List("cert/")
 	if err != nil {
-		b.Logger().Printf("[ERR] cert: failed to list trusted certs: %v", err)
+		b.Logger().Error("cert: failed to list trusted certs", "error", err)
 		return
 	}
 	for _, name := range names {
 		entry, err := b.Cert(store, strings.TrimPrefix(name, "cert/"))
 		if err != nil {
-			b.Logger().Printf("[ERR] cert: failed to load trusted certs '%s': %v", name, err)
+			b.Logger().Error("cert: failed to load trusted cert", "name", name, "error", err)
 			continue
 		}
 		parsed := parsePEM([]byte(entry.Certificate))
 		if len(parsed) == 0 {
-			b.Logger().Printf("[ERR] cert: failed to parse certificate for '%s'", name)
+			b.Logger().Error("cert: failed to parse certificate", "name", name)
 			continue
 		}
 		if !parsed[0].IsCA {

builtin/credential/github/path_login.go

@@ -48,7 +48,7 @@ func (b *backend) pathLogin(
 
 	ttl, _, err := b.SanitizeTTLStr(config.TTL.String(), config.MaxTTL.String())
 	if err != nil {
-		return logical.ErrorResponse(fmt.Sprintf("[ERR]:%s", err)), nil
+		return logical.ErrorResponse(fmt.Sprintf("error sanitizing TTLs: %s", err)), nil
 	}
 
 	return &logical.Response{

builtin/credential/ldap/backend.go

@@ -105,7 +105,9 @@ func (b *backend) Login(req *logical.Request, username string, password string)
 		return nil, logical.ErrorResponse(err.Error()), nil
 	}
 
-	b.Logger().Printf("[DEBUG] auth/ldap: BindDN for %s is %s", username, bindDN)
+	if b.Logger().IsDebug() {
+		b.Logger().Debug("auth/ldap: BindDN fetched", "username", username, "binddn", bindDN)
+	}
 
 	// Try to bind as the login user. This is where the actual authentication takes place.
 	if err = c.Bind(bindDN, password); err != nil {
@@ -121,7 +123,9 @@ func (b *backend) Login(req *logical.Request, username string, password string)
 	if err != nil {
 		return nil, logical.ErrorResponse(err.Error()), nil
 	}
-	b.Logger().Printf("[DEBUG] auth/ldap: Server returned %d groups: %v", len(ldapGroups), ldapGroups)
+	if b.Logger().IsDebug() {
+		b.Logger().Debug("auth/ldap: Groups fetched from server", "num_server_groups", len(ldapGroups), "server_groups", ldapGroups)
+	}
 
 	ldapResponse := &logical.Response{
 		Data: map[string]interface{}{},
@@ -137,7 +141,9 @@ func (b *backend) Login(req *logical.Request, username string, password string)
 	// Import the custom added groups from ldap backend
 	user, err := b.User(req.Storage, username)
 	if err == nil && user != nil && user.Groups != nil {
-		b.Logger().Printf("[DEBUG] auth/ldap: adding %d local groups: %v\n", len(user.Groups), user.Groups)
+		if b.Logger().IsDebug() {
+			b.Logger().Debug("auth/ldap: adding local groups", "num_local_groups", len(user.Groups), "local_groups", user.Groups)
+		}
 		allGroups = append(allGroups, user.Groups...)
 	}
 	// Merge local and LDAP groups
@@ -207,7 +213,9 @@ func (b *backend) getBindDN(cfg *ConfigEntry, c *ldap.Conn, username string) (st
 		}
 
 		filter := fmt.Sprintf("(%s=%s)", cfg.UserAttr, ldap.EscapeFilter(username))
-		b.Logger().Printf("[DEBUG] auth/ldap: Discovering user, BaseDN=%s, Filter=%s", cfg.UserDN, filter)
+		if b.Logger().IsDebug() {
+			b.Logger().Debug("auth/ldap: Discovering user", "userdn", cfg.UserDN, "filter", filter)
+		}
 		result, err := c.Search(&ldap.SearchRequest{
 			BaseDN: cfg.UserDN,
 			Scope:  2, // subtree
@@ -239,7 +247,9 @@ func (b *backend) getUserDN(cfg *ConfigEntry, c *ldap.Conn, bindDN string) (stri
 	if cfg.UPNDomain != "" {
 		// Find the distinguished name for the user if userPrincipalName used for login
 		filter := fmt.Sprintf("(userPrincipalName=%s)", ldap.EscapeFilter(bindDN))
-		b.Logger().Printf("[DEBUG] auth/ldap: Searching UPN, BaseDN=%s, Filter=%s", cfg.UserDN, filter)
+		if b.Logger().IsDebug() {
+			b.Logger().Debug("auth/ldap: Searching UPN", "userdn", cfg.UserDN, "filter", filter)
+		}
 		result, err := c.Search(&ldap.SearchRequest{
 			BaseDN: cfg.UserDN,
 			Scope:  2, // subtree
@@ -281,18 +291,20 @@ func (b *backend) getLdapGroups(cfg *ConfigEntry, c *ldap.Conn, userDN string, u
 	ldapMap := make(map[string]bool)
 
 	if cfg.GroupFilter == "" {
-		b.Logger().Printf("[WARN] auth/ldap: GroupFilter is empty, will not query server")
+		b.Logger().Warn("auth/ldap: GroupFilter is empty, will not query server")
 		return make([]string, 0), nil
 	}
 
 	if cfg.GroupDN == "" {
-		b.Logger().Printf("[WARN] auth/ldap: GroupDN is empty, will not query server")
+		b.Logger().Warn("auth/ldap: GroupDN is empty, will not query server")
 		return make([]string, 0), nil
 	}
 
 	// If groupfilter was defined, resolve it as a Go template and use the query for
 	// returning the user's groups
-	b.Logger().Printf("[DEBUG] auth/ldap: Compiling group filter %s", cfg.GroupFilter)
+	if b.Logger().IsDebug() {
+		b.Logger().Debug("auth/ldap: Compiling group filter", "group_filter", cfg.GroupFilter)
+	}
 
 	// Parse the configuration as a template.
 	// Example template "(&(objectClass=group)(member:1.2.840.113556.1.4.1941:={{.UserDN}}))"
@@ -313,7 +325,9 @@ func (b *backend) getLdapGroups(cfg *ConfigEntry, c *ldap.Conn, userDN string, u
 	var renderedQuery bytes.Buffer
 	t.Execute(&renderedQuery, context)
 
-	b.Logger().Printf("[DEBUG] auth/ldap: Searching GroupDN=%s, query=%s", cfg.GroupDN, renderedQuery.String())
+	if b.Logger().IsDebug() {
+		b.Logger().Debug("auth/ldap: Searching", "groupdn", cfg.GroupDN, "rendered_query", renderedQuery.String())
+	}
 
 	result, err := c.Search(&ldap.SearchRequest{
 		BaseDN: cfg.GroupDN,

builtin/logical/mongodb/backend_test.go

@@ -7,12 +7,12 @@ import (
 	"strings"
 	"sync"
 	"testing"
+	"time"
 
 	"github.com/hashicorp/vault/logical"
 	logicaltest "github.com/hashicorp/vault/logical/testing"
 	"github.com/mitchellh/mapstructure"
 	"github.com/ory-am/dockertest"
-	"time"
 )
 
 var (

builtin/logical/pki/path_fetch.go

@@ -191,7 +191,9 @@ reply:
 				logical.HTTPRawBody:     certificate,
 			}}
 		if retErr != nil {
-			b.Logger().Printf("Possible error, but cannot return in raw response: %s. Note that an empty CA probably means none was configured, and an empty CRL is quite possibly correct", retErr)
+			if b.Logger().IsWarn() {
+				b.Logger().Warn("Possible error, but cannot return in raw response. Note that an empty CA probably means none was configured, and an empty CRL is possibly correct", "error", retErr)
+			}
 		}
 		retErr = nil
 		response.Data[logical.HTTPStatusCode] = 200

builtin/logical/postgresql/backend.go

@@ -3,10 +3,11 @@ package postgresql
 import (
 	"database/sql"
 	"fmt"
-	"log"
 	"strings"
 	"sync"
 
+	log "github.com/mgutz/logxi/v1"
+
 	"github.com/hashicorp/vault/logical"
 	"github.com/hashicorp/vault/logical/framework"
 )
@@ -45,13 +46,14 @@ type backend struct {
 	db   *sql.DB
 	lock sync.Mutex
 
-	logger *log.Logger
+	logger log.Logger
 }
 
 // DB returns the database connection.
 func (b *backend) DB(s logical.Storage) (*sql.DB, error) {
-	b.logger.Println("[TRACE] postgres/db: enter")
-	defer b.logger.Println("[TRACE] postgres/db: exit")
+	b.logger.Trace("postgres/db: enter")
+	defer b.logger.Trace("postgres/db: exit")
+
 	b.lock.Lock()
 	defer b.lock.Unlock()
 
@@ -111,8 +113,8 @@ func (b *backend) DB(s logical.Storage) (*sql.DB, error) {
 
 // ResetDB forces a connection next time DB() is called.
 func (b *backend) ResetDB() {
-	b.logger.Println("[TRACE] postgres/resetdb: enter")
-	defer b.logger.Println("[TRACE] postgres/resetdb: exit")
+	b.logger.Trace("postgres/resetdb: enter")
+	defer b.logger.Trace("postgres/resetdb: exit")
 
 	b.lock.Lock()
 	defer b.lock.Unlock()

builtin/logical/postgresql/path_role_create.go

@@ -33,12 +33,13 @@ func pathRoleCreate(b *backend) *framework.Path {
 
 func (b *backend) pathRoleCreateRead(
 	req *logical.Request, data *framework.FieldData) (*logical.Response, error) {
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: enter")
-	defer b.logger.Println("[TRACE] postgres/pathRoleCreateRead: exit")
+	b.logger.Trace("postgres/pathRoleCreateRead: enter")
+	defer b.logger.Trace("postgres/pathRoleCreateRead: exit")
+
 	name := data.Get("name").(string)
 
 	// Get the role
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: getting role")
+	b.logger.Trace("postgres/pathRoleCreateRead: getting role")
 	role, err := b.Role(req.Storage, name)
 	if err != nil {
 		return nil, err
@@ -48,7 +49,7 @@ func (b *backend) pathRoleCreateRead(
 	}
 
 	// Determine if we have a lease
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: getting lease")
+	b.logger.Trace("postgres/pathRoleCreateRead: getting lease")
 	lease, err := b.Lease(req.Storage)
 	if err != nil {
 		return nil, err
@@ -84,20 +85,20 @@ func (b *backend) pathRoleCreateRead(
 		Format("2006-01-02 15:04:05-0700")
 
 	// Get our handle
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: getting database handle")
+	b.logger.Trace("postgres/pathRoleCreateRead: getting database handle")
 	db, err := b.DB(req.Storage)
 	if err != nil {
 		return nil, err
 	}
 
 	// Start a transaction
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: starting transaction")
+	b.logger.Trace("postgres/pathRoleCreateRead: starting transaction")
 	tx, err := db.Begin()
 	if err != nil {
 		return nil, err
 	}
 	defer func() {
-		b.logger.Println("[TRACE] postgres/pathRoleCreateRead: rolling back transaction")
+		b.logger.Trace("postgres/pathRoleCreateRead: rolling back transaction")
 		tx.Rollback()
 	}()
 
@@ -108,7 +109,7 @@ func (b *backend) pathRoleCreateRead(
 			continue
 		}
 
-		b.logger.Println("[TRACE] postgres/pathRoleCreateRead: preparing statement")
+		b.logger.Trace("postgres/pathRoleCreateRead: preparing statement")
 		stmt, err := tx.Prepare(Query(query, map[string]string{
 			"name":       username,
 			"password":   password,
@@ -118,22 +119,22 @@ func (b *backend) pathRoleCreateRead(
 			return nil, err
 		}
 		defer stmt.Close()
-		b.logger.Println("[TRACE] postgres/pathRoleCreateRead: executing statement")
+		b.logger.Trace("postgres/pathRoleCreateRead: executing statement")
 		if _, err := stmt.Exec(); err != nil {
 			return nil, err
 		}
 	}
 
 	// Commit the transaction
 
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: committing transaction")
+	b.logger.Trace("postgres/pathRoleCreateRead: committing transaction")
 	if err := tx.Commit(); err != nil {
 		return nil, err
 	}
 
 	// Return the secret
 
-	b.logger.Println("[TRACE] postgres/pathRoleCreateRead: generating secret")
+	b.logger.Trace("postgres/pathRoleCreateRead: generating secret")
 	resp := b.Secret(SecretCredsType).Response(map[string]interface{}{
 		"username": username,
 		"password": password,

builtin/logical/ssh/communicator.go

@@ -7,11 +7,12 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"net"
 	"os"
 	"path/filepath"
 
+	log "github.com/mgutz/logxi/v1"
+
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/crypto/ssh/agent"
 )
@@ -38,6 +39,9 @@ type SSHCommConfig struct {
 
 	// DisableAgent, if true, will not forward the SSH agent.
 	DisableAgent bool
+
+	// Logger for output
+	Logger log.Logger
 }
 
 // Creates a new communicator implementation over SSH. This takes
@@ -92,8 +96,9 @@ func (c *comm) NewSession() (session *ssh.Session, err error) {
 	}
 
 	if err != nil {
-		log.Printf("ssh session open error: '%s', attempting reconnect", err)
+		c.config.Logger.Error("ssh session open error, attempting reconnect", "error", err)
 		if err := c.reconnect(); err != nil {
+			c.config.Logger.Error("reconnect attempt failed", "error", err)
 			return nil, err
 		}
 
@@ -119,13 +124,13 @@ func (c *comm) reconnect() error {
 		//
 		// http://golang.org/doc/faq#nil_error
 		c.conn = nil
-		log.Printf("reconnection error: %s", err)
+		c.config.Logger.Error("reconnection error", "error", err)
 		return err
 	}
 
 	sshConn, sshChan, req, err := ssh.NewClientConn(c.conn, c.address, c.config.SSHConfig)
 	if err != nil {
-		log.Printf("handshake error: %s", err)
+		c.config.Logger.Error("handshake error", "error", err)
 		c.Close()
 		return err
 	}
@@ -153,15 +158,15 @@ func (c *comm) connectToAgent() {
 	}
 	agentConn, err := net.Dial("unix", socketLocation)
 	if err != nil {
-		log.Printf("[ERROR] could not connect to local agent socket: %s", socketLocation)
+		c.config.Logger.Error("could not connect to local agent socket", "socket_path", socketLocation)
 		return
 	}
 	defer agentConn.Close()
 
 	// create agent and add in auth
 	forwardingAgent := agent.NewClient(agentConn)
 	if forwardingAgent == nil {
-		log.Printf("[ERROR] Could not create agent client")
+		c.config.Logger.Error("could not create agent client")
 		return
 	}
 
@@ -180,7 +185,7 @@ func (c *comm) connectToAgent() {
 
 	err = agent.RequestAgentForwarding(session)
 	if err != nil {
-		log.Printf("[ERROR] RequestAgentForwarding: %#v", err)
+		c.config.Logger.Error("error requesting agent forwarding", "error", err)
 		return
 	}
 	return
@@ -243,7 +248,7 @@ func (c *comm) scpSession(scpCommand string, f func(io.Writer, *bufio.Reader) er
 		if exitErr, ok := err.(*ssh.ExitError); ok {
 			// Otherwise, we have an ExitErorr, meaning we can just read
 			// the exit status
-			log.Printf("non-zero exit status: %d", exitErr.ExitStatus())
+			c.config.Logger.Error("got non-zero exit status", "exit_status", exitErr.ExitStatus())
 
 			// If we exited with status 127, it means SCP isn't available.
 			// Return a more descriptive error for that.