Use levelled logger (#63)

* Use levelled logger
* Fix log level input, add test readme, remove test for log lines
* Add changelog note

Co-authored-by: Theron Voran <[email protected]>

Author: tomhjp

CHANGELOG.md

@@ -1,5 +1,13 @@
 ## Unreleased
 
+CHANGES:
+
+* Logging is now levelled and less chatty by default. Level can be controlled by VAULT_LOG_LEVEL environment variable. [[GH-63](https://github.com/hashicorp/vault-lambda-extension/pull/63)]
+
+IMPROVEMENTS:
+
+* Leading and trailing whitespace is trimmed from environment variable values on reading. [[GH-63](https://github.com/hashicorp/vault-lambda-extension/pull/63)]
+
 ## 0.5.0 (August 24, 2021)
 
 FEATURES:

README.md

@@ -152,6 +152,7 @@ Environment variable              | Description | Required | Example value
 `VAULT_SECRET_FILE_FOO`           | Must exist for any correspondingly named `VAULT_SECRET_PATH_FOO`. Name has no further effect beyond matching to the correct path variable | No | `/tmp/token`
 `VAULT_TOKEN_EXPIRY_GRACE_PERIOD` | Period at the end of the proxy server's auth token TTL where it will consider the token expired and attempt to re-authenticate to Vault. Must have a unit and be parseable by `time.Duration`. Defaults to 10s. | No | `1m`
 `VAULT_STS_ENDPOINT_REGION`       | The region of the STS regional endpoint to authenticate with. If the AWS IAM auth mount specified uses a regional STS endpoint, then this needs to match the region of that endpoint. Defaults to using the global endpoint, or the region the Lambda resides in if `AWS_STS_REGIONAL_ENDPOINTS` is set to `regional` | No | `eu-west-1`
+`VAULT_LOG_LEVEL`                 | Log level, one of TRACE, DEBUG, INFO, WARN, ERROR, OFF. Defaults to INFO. | No | `DEBUG`
 
 The remaining environment variables are not required, and function exactly as
 described in the [Vault Commands (CLI)][vault-env-vars] documentation. However,

go.mod

@@ -4,6 +4,7 @@ go 1.17
 
 require (
 	github.com/aws/aws-sdk-go v1.41.10
+	github.com/hashicorp/go-hclog v1.1.0
 	github.com/hashicorp/go-multierror v1.1.1
 	github.com/hashicorp/vault/api v1.4.1
 	github.com/hashicorp/vault/sdk v0.4.1
@@ -21,7 +22,6 @@ require (
 	github.com/golang/snappy v0.0.4 // indirect
 	github.com/hashicorp/errwrap v1.1.0 // indirect
 	github.com/hashicorp/go-cleanhttp v0.5.2 // indirect
-	github.com/hashicorp/go-hclog v0.16.2 // indirect
 	github.com/hashicorp/go-immutable-radix v1.3.1 // indirect
 	github.com/hashicorp/go-plugin v1.4.3 // indirect
 	github.com/hashicorp/go-retryablehttp v0.6.6 // indirect

go.sum

@@ -97,8 +97,9 @@ github.com/hashicorp/go-cleanhttp v0.5.2 h1:035FKYIWjmULyFRBKPs8TBQoi0x6d9G4xc9n
 github.com/hashicorp/go-cleanhttp v0.5.2/go.mod h1:kO/YDlP8L1346E6Sodw+PrpBSV4/SoxCXGY6BqNFT48=
 github.com/hashicorp/go-hclog v0.9.2/go.mod h1:5CU+agLiy3J7N7QjHK5d05KxGsuXiQLrjA0H7acj2lQ=
 github.com/hashicorp/go-hclog v0.14.1/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
-github.com/hashicorp/go-hclog v0.16.2 h1:K4ev2ib4LdQETX5cSZBG0DVLk1jwGqSPXBjdah3veNs=
 github.com/hashicorp/go-hclog v0.16.2/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
+github.com/hashicorp/go-hclog v1.1.0 h1:QsGcniKx5/LuX2eYoeL+Np3UKYPNaN7YKpTh29h8rbw=
+github.com/hashicorp/go-hclog v1.1.0/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
 github.com/hashicorp/go-immutable-radix v1.0.0/go.mod h1:0y9vanUI8NX6FsYoO3zeMjhV/C5i9g4Q3DwcSNZ4P60=
 github.com/hashicorp/go-immutable-radix v1.3.1 h1:DKHmCUm2hRBK510BaiZlwvpD40f8bJFeZnpfm2KLowc=
 github.com/hashicorp/go-immutable-radix v1.3.1/go.mod h1:0y9vanUI8NX6FsYoO3zeMjhV/C5i9g4Q3DwcSNZ4P60=

internal/config/auth.go

@@ -2,6 +2,7 @@ package config
 
 import (
 	"os"
+	"strings"
 )
 
 const (
@@ -24,10 +25,10 @@ type AuthConfig struct {
 // AuthConfigFromEnv reads config from the environment for authenticating to Vault.
 func AuthConfigFromEnv() AuthConfig {
 	return AuthConfig{
-		Role:              os.Getenv(vaultAuthRole),
-		Provider:          os.Getenv(vaultAuthProvider),
-		IAMServerID:       os.Getenv(vaultIAMServerID),
-		STSEndpointRegion: os.Getenv(stsEndpointRegionEnv),
-		VaultAddress:      os.Getenv(vleVaultAddr),
+		Role:              strings.TrimSpace(os.Getenv(vaultAuthRole)),
+		Provider:          strings.TrimSpace(os.Getenv(vaultAuthProvider)),
+		IAMServerID:       strings.TrimSpace(os.Getenv(vaultIAMServerID)),
+		STSEndpointRegion: strings.TrimSpace(os.Getenv(stsEndpointRegionEnv)),
+		VaultAddress:      strings.TrimSpace(os.Getenv(vleVaultAddr)),
 	}
 }

internal/config/cache.go

@@ -3,6 +3,7 @@ package config
 import (
 	"os"
 	"strconv"
+	"strings"
 	"time"
 )
 
@@ -26,7 +27,7 @@ type CacheConfig struct {
 // CacheConfigFromEnv reads config from the environment for caching
 func CacheConfigFromEnv() CacheConfig {
 	var cacheTTL time.Duration
-	cacheTTLEnv := os.Getenv(VaultCacheTTL)
+	cacheTTLEnv := strings.TrimSpace(os.Getenv(VaultCacheTTL))
 	if cacheTTLEnv != "" {
 		var err error
 		cacheTTL, err = time.ParseDuration(cacheTTLEnv)
@@ -36,7 +37,7 @@ func CacheConfigFromEnv() CacheConfig {
 	}
 
 	defaultOn := false
-	defaultOnEnv := os.Getenv(VaultCacheEnabled)
+	defaultOnEnv := strings.TrimSpace(os.Getenv(VaultCacheEnabled))
 	if defaultOnEnv != "" {
 		var err error
 		defaultOn, err = strconv.ParseBool(defaultOnEnv)

internal/config/secret.go

@@ -68,7 +68,7 @@ func ParseConfiguredSecrets() ([]ConfiguredSecret, error) {
 			return nil, fmt.Errorf("os.Environ should return key=value pairs, but got %s", kv)
 		}
 		key := parts[0]
-		value := parts[1]
+		value := strings.TrimSpace(parts[1])
 
 		switch {
 		case strings.HasPrefix(key, vaultSecretPathPrefix):
@@ -105,12 +105,12 @@ func ParseConfiguredSecrets() ([]ConfiguredSecret, error) {
 	}
 
 	// Special case for anonymous-name secret
-	anonymousSecretVaultPath := getenv(vaultSecretPathKey)
+	anonymousSecretVaultPath := strings.TrimSpace(getenv(vaultSecretPathKey))
 	if anonymousSecretVaultPath != "" {
 		s := &ConfiguredSecret{
 			name:      "",
 			VaultPath: anonymousSecretVaultPath,
-			FilePath:  filePathFromEnv(getenv(vaultSecretFileKey)),
+			FilePath:  filePathFromEnv(strings.TrimSpace(getenv(vaultSecretFileKey))),
 		}
 		if s.FilePath == "" {
 			s.FilePath = path.Join(DefaultSecretDirectory, DefaultSecretFile)

internal/proxy/cache.go

@@ -6,10 +6,10 @@ import (
 	"encoding/hex"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"strings"
 
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault-lambda-extension/internal/config"
 	"github.com/hashicorp/vault/api"
 	"github.com/hashicorp/vault/sdk/helper/cryptoutil"
@@ -70,19 +70,19 @@ func NewCache(cc config.CacheConfig) *Cache {
 
 // constructs the CacheKey for this request and token and returns the SHA256
 // hash
-func makeRequestHash(logger *log.Logger, r *http.Request, token string) (string, error) {
+func makeRequestHash(logger hclog.Logger, r *http.Request, token string) (string, error) {
 	reqBody, err := ioutil.ReadAll(r.Body)
 	if err != nil {
 		if r.Body != nil {
 			if err := r.Body.Close(); err != nil {
-				logger.Printf("error closing request body: %s", err)
+				logger.Error("error closing request body", "error", err)
 			}
 		}
 		return "", fmt.Errorf("failed to read request body: %w", err)
 	}
 	if r.Body != nil {
 		if err := r.Body.Close(); err != nil {
-			logger.Printf("error closing request body: %s", err)
+			logger.Error("error closing request body", "error", err)
 		}
 	}
 	r.Body = ioutil.NopCloser(bytes.NewReader(reqBody))

internal/proxy/cache_test.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"math/rand"
 	"net/http"
 	"net/http/httptest"
@@ -14,6 +13,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault-lambda-extension/internal/config"
 	"github.com/hashicorp/vault/api"
 	"github.com/hashicorp/vault/sdk/helper/consts"
@@ -198,7 +198,7 @@ func Test_makeRequestHash(t *testing.T) {
 		},
 	}
 
-	h, err := makeRequestHash(log.Default(), req, "blue")
+	h, err := makeRequestHash(hclog.Default(), req, "blue")
 	assert.NoError(t, err)
 	assert.Equal(t, "b62adf8925f91450ee992596dd2fb38edb0d3270ed9edc23b98bf5f322e9ed9a", h)
 }

internal/proxy/proxy.go

@@ -4,10 +4,10 @@ import (
 	"bytes"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"net/url"
 
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault-lambda-extension/internal/config"
 	"github.com/hashicorp/vault-lambda-extension/internal/vault"
 	"github.com/hashicorp/vault/sdk/helper/consts"
@@ -19,7 +19,7 @@ const (
 )
 
 // New returns an unstarted HTTP server with health and proxy handlers.
-func New(logger *log.Logger, client *vault.Client, cacheConfig config.CacheConfig) *http.Server {
+func New(logger hclog.Logger, client *vault.Client, cacheConfig config.CacheConfig) *http.Server {
 	cache := setupCache(cacheConfig)
 	mux := http.ServeMux{}
 	mux.HandleFunc("/", proxyHandler(logger, client, cache))
@@ -32,15 +32,15 @@ func New(logger *log.Logger, client *vault.Client, cacheConfig config.CacheConfi
 
 // The proxyHandler borrows from the Send function in Vault Agent's proxy:
 // https://github.com/hashicorp/vault/blob/22b486b651b8956d32fb24e77cef4050df7094b6/command/agent/cache/api_proxy.go
-func proxyHandler(logger *log.Logger, client *vault.Client, cache *Cache) func(http.ResponseWriter, *http.Request) {
+func proxyHandler(logger hclog.Logger, client *vault.Client, cache *Cache) func(http.ResponseWriter, *http.Request) {
 	return func(w http.ResponseWriter, r *http.Request) {
 		token, err := client.Token(r.Context())
 		if err != nil {
 			http.Error(w, fmt.Sprintf("failed to get valid Vault token: %s", err), http.StatusInternalServerError)
 			return
 		}
 
-		logger.Printf("Proxying %s %s\n", r.Method, r.URL.Path)
+		logger.Debug(fmt.Sprintf("Proxying %s %s", r.Method, r.URL.Path))
 		fwReq, err := proxyRequest(r, client.VaultConfig.Address, token)
 		if err != nil {
 			http.Error(w, fmt.Sprintf("failed to generate proxy request: %s", err), http.StatusInternalServerError)
@@ -57,7 +57,7 @@ func proxyHandler(logger *log.Logger, client *vault.Client, cache *Cache) func(h
 			// Construct the hash for this request to use as the cache key
 			cacheKeyHash, err = makeRequestHash(logger, r, token)
 			if err != nil {
-				logger.Printf("failed to compute request hash: %s", err)
+				logger.Error("failed to compute request hash", "error", err)
 				http.Error(w, "failed to read request", http.StatusInternalServerError)
 				return
 			}
@@ -71,10 +71,10 @@ func proxyHandler(logger *log.Logger, client *vault.Client, cache *Cache) func(h
 			// Check the cache for this request
 			data, err := cache.Get(cacheKeyHash)
 			if err != nil {
-				logger.Printf("failed to fetch from cache: %s", err)
+				logger.Error("failed to fetch from cache", "error", err)
 			}
 			if data != nil {
-				logger.Printf("Cache hit for: %s %s", r.Method, r.URL.Path)
+				logger.Debug(fmt.Sprintf("Cache hit for: %s %s", r.Method, r.URL.Path))
 				fetchFromCache(w, data)
 				return
 			}
@@ -99,7 +99,7 @@ func proxyHandler(logger *log.Logger, client *vault.Client, cache *Cache) func(h
 
 		if doCacheSet && resp.StatusCode < 300 {
 			cache.Set(cacheKeyHash, retrieveData(resp, respBody))
-			logger.Printf("Refreshed cache for: %s %s", r.Method, r.URL.Path)
+			logger.Debug(fmt.Sprintf("Refreshed cache for: %s %s", r.Method, r.URL.Path))
 		}
 
 		copyHeaders(w.Header(), resp.Header)
@@ -111,7 +111,7 @@ func proxyHandler(logger *log.Logger, client *vault.Client, cache *Cache) func(h
 			return
 		}
 
-		logger.Printf("Successfully proxied %s %s\n", r.Method, r.URL.Path)
+		logger.Debug(fmt.Sprintf("Successfully proxied %s %s", r.Method, r.URL.Path))
 	}
 }
 

internal/proxy/proxy_test.go

@@ -5,14 +5,14 @@ import (
 	"errors"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"net/http/httptest"
 	"strings"
 	"testing"
 
 	"github.com/aws/aws-sdk-go/aws/session"
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault-lambda-extension/internal/config"
 	"github.com/hashicorp/vault-lambda-extension/internal/ststest"
 	"github.com/hashicorp/vault-lambda-extension/internal/vault"
@@ -111,12 +111,12 @@ func startProxy(t *testing.T, vaultAddress string, ses *session.Session) (string
 	vaultConfig := api.DefaultConfig()
 	require.NoError(t, vaultConfig.Error)
 	vaultConfig.Address = vaultAddress
-	client, err := vault.NewClient(log.New(ioutil.Discard, "", 0), vaultConfig, config.AuthConfig{}, ses)
+	client, err := vault.NewClient(hclog.NewNullLogger(), vaultConfig, config.AuthConfig{}, ses)
 	require.NoError(t, err)
 	client.VaultConfig.Address = vaultAddress
 	ln, err := net.Listen("tcp", "127.0.0.1:0")
 	require.NoError(t, err)
-	proxy := New(log.New(ioutil.Discard, "", 0), client, config.CacheConfig{})
+	proxy := New(hclog.NewNullLogger(), client, config.CacheConfig{})
 	go func() {
 		_ = proxy.Serve(ln)
 	}()

internal/vault/client.go

@@ -6,13 +6,14 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
+	"strings"
 	"sync"
 	"time"
 
 	"github.com/aws/aws-sdk-go/aws/session"
 	"github.com/aws/aws-sdk-go/service/sts"
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault-lambda-extension/internal/config"
 	"github.com/hashicorp/vault/api"
 )
@@ -29,7 +30,7 @@ type Client struct {
 	VaultClient *api.Client
 	VaultConfig *api.Config
 
-	logger     *log.Logger
+	logger     hclog.Logger
 	stsSvc     *sts.STS
 	authConfig config.AuthConfig
 
@@ -42,7 +43,7 @@ type Client struct {
 
 // NewClient uses the AWS IAM auth method configured in a Vault cluster to
 // authenticate the execution role and create a Vault API client.
-func NewClient(logger *log.Logger, vaultConfig *api.Config, authConfig config.AuthConfig, awsSes *session.Session) (*Client, error) {
+func NewClient(logger hclog.Logger, vaultConfig *api.Config, authConfig config.AuthConfig, awsSes *session.Session) (*Client, error) {
 	vaultClient, err := api.NewClient(vaultConfig)
 	if err != nil {
 		return nil, fmt.Errorf("error making extension: %w", err)
@@ -73,17 +74,17 @@ func (c *Client) Token(ctx context.Context) (string, error) {
 	defer c.mtx.Unlock()
 
 	if c.expired() {
-		c.logger.Println("authenticating to Vault")
+		c.logger.Debug("authenticating to Vault")
 		err := c.login(ctx)
 		if err != nil {
 			return "", err
 		}
 	} else if c.shouldRenew() {
 		// Renew but don't retry or bail on errors, just best effort.
-		c.logger.Println("renewing Vault token")
+		c.logger.Debug("renewing Vault token")
 		err := c.renew()
 		if err != nil {
-			c.logger.Printf("failed to renew token but attempting to continue: %s\n", err)
+			c.logger.Error("failed to renew token but attempting to continue", "error", err)
 		}
 	}
 
@@ -179,7 +180,7 @@ func parseTokenExpiryGracePeriod() (time.Duration, error) {
 	var err error
 	expiryGracePeriod := defaultTokenExpiryGracePeriod
 
-	expiryGracePeriodString := os.Getenv(tokenExpiryGracePeriodEnv)
+	expiryGracePeriodString := strings.TrimSpace(os.Getenv(tokenExpiryGracePeriodEnv))
 	if expiryGracePeriodString != "" {
 		expiryGracePeriod, err = time.ParseDuration(expiryGracePeriodString)
 		if err != nil {