add debug logs in initialization step (#116)

Author: raymonstah

CHANGELOG.md

@@ -1,7 +1,10 @@
 ## Unreleased
 
+## 0.10.1 (July 10, 2023)
+
 IMPROVEMENTS:
 * quick-start: Update Postgres version to 14.7
+* Add debug logs during initialization step
 
 ## 0.10.0 (March 30, 2023)
 

internal/vault/client.go

@@ -21,8 +21,9 @@ import (
 	"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"
+
+	"github.com/hashicorp/vault-lambda-extension/internal/config"
 )
 
 const (
@@ -82,6 +83,8 @@ func NewClient(name, version string, logger hclog.Logger, vaultConfig *api.Confi
 
 // Token synchronously renews/re-auths as required and returns a Vault token.
 func (c *Client) Token(ctx context.Context) (string, error) {
+	start := time.Now()
+	c.logger.Debug("fetching token")
 	c.mtx.Lock()
 	defer c.mtx.Unlock()
 
@@ -100,6 +103,7 @@ func (c *Client) Token(ctx context.Context) (string, error) {
 		}
 	}
 
+	c.logger.Debug(fmt.Sprintf("fetched token in %v", time.Since(start)))
 	return c.VaultClient.Token(), nil
 }
 

main.go

@@ -15,17 +15,19 @@ import (
 	"path"
 	"sync"
 	"syscall"
+	"time"
 
 	"github.com/aws/aws-sdk-go/aws"
 	"github.com/aws/aws-sdk-go/aws/endpoints"
 	"github.com/aws/aws-sdk-go/aws/session"
 	"github.com/hashicorp/go-hclog"
+	"github.com/hashicorp/vault/api"
+
 	"github.com/hashicorp/vault-lambda-extension/internal/config"
 	"github.com/hashicorp/vault-lambda-extension/internal/extension"
 	"github.com/hashicorp/vault-lambda-extension/internal/proxy"
 	"github.com/hashicorp/vault-lambda-extension/internal/runmode"
 	"github.com/hashicorp/vault-lambda-extension/internal/vault"
-	"github.com/hashicorp/vault/api"
 )
 
 func main() {
@@ -107,6 +109,7 @@ func (h *handler) handle() error {
 }
 
 func (h *handler) runExtension(ctx context.Context, wg *sync.WaitGroup) (func(context.Context) error, error) {
+	start := time.Now()
 	h.logger.Info("Initialising")
 
 	authConfig := config.AuthConfigFromEnv()
@@ -154,7 +157,7 @@ func (h *handler) runExtension(ctx context.Context, wg *sync.WaitGroup) (func(co
 	client.VaultClient = client.VaultClient.WithRequestCallbacks(api.RequireState(newState), vault.UserAgentRequestCallback(uaFunc)).WithResponseCallbacks()
 
 	if h.runMode.HasModeFile() {
-		if err := writePreconfiguredSecrets(client.VaultClient); err != nil {
+		if err := writePreconfiguredSecrets(h.logger, client.VaultClient); err != nil {
 			return nil, err
 		}
 	}
@@ -164,6 +167,8 @@ func (h *handler) runExtension(ctx context.Context, wg *sync.WaitGroup) (func(co
 
 	cleanupFunc := func(context.Context) error { return nil }
 	if h.runMode.HasModeProxy() {
+		start := time.Now()
+		h.logger.Debug("initialising proxy mode")
 		ln, err := net.Listen("tcp", "127.0.0.1:8200")
 		if err != nil {
 			return nil, fmt.Errorf("failed to listen on port 8200: %w", err)
@@ -181,14 +186,17 @@ func (h *handler) runExtension(ctx context.Context, wg *sync.WaitGroup) (func(co
 		cleanupFunc = func(ctx context.Context) error {
 			return srv.Shutdown(ctx)
 		}
+		h.logger.Debug(fmt.Sprintf("proxy mode initialised in %v", time.Since(start)))
 	}
 
-	h.logger.Info("Initialised")
+	h.logger.Info(fmt.Sprintf("Initialised in %v", time.Since(start)))
 	return cleanupFunc, nil
 }
 
 // writePreconfiguredSecrets writes secrets to disk.
-func writePreconfiguredSecrets(client *api.Client) error {
+func writePreconfiguredSecrets(logger hclog.Logger, client *api.Client) error {
+	start := time.Now()
+	logger.Debug("writing secrets to disk")
 	configuredSecrets, err := config.ParseConfiguredSecrets()
 	if err != nil {
 		return fmt.Errorf("failed to parse configured secrets to read: %w", err)
@@ -218,6 +226,7 @@ func writePreconfiguredSecrets(client *api.Client) error {
 		}
 	}
 
+	logger.Debug(fmt.Sprintf("wrote secrets to disk in %v", time.Since(start)))
 	return nil
 }
 

quick-start/terraform/lambda.tf

@@ -9,27 +9,30 @@ resource "aws_lambda_function" "function" {
   handler       = "main"
   runtime       = "provided.al2"
   architectures = ["x86_64"]
-  layers        = var.local_extension ? ["${aws_lambda_layer_version.vle[0].arn}"] : ["arn:aws:lambda:${var.aws_region}:634166935893:layer:vault-lambda-extension:16"]
+  layers        = var.local_extension ? ["${aws_lambda_layer_version.vle[0].arn}"] : [
+    "arn:aws:lambda:${var.aws_region}:634166935893:layer:vault-lambda-extension:16"
+  ]
 
   environment {
     variables = {
-      VAULT_ADDR           = "http://${aws_instance.vault-server.public_ip}:8200",
-      VAULT_AUTH_ROLE      = aws_iam_role.lambda.name,
-      VAULT_AUTH_PROVIDER  = "aws",
-      VAULT_SECRET_PATH_DB = "database/creds/lambda-function",
-      VAULT_SECRET_FILE_DB = "/tmp/vault_secret.json",
-      VAULT_SECRET_PATH    = "secret/myapp/config",
+      VAULT_ADDR             = "http://${aws_instance.vault-server.public_ip}:8200",
+      VAULT_AUTH_ROLE        = aws_iam_role.lambda.name,
+      VAULT_AUTH_PROVIDER    = "aws",
+      VAULT_SECRET_PATH_DB   = "database/creds/lambda-function",
+      VAULT_SECRET_FILE_DB   = "/tmp/vault_secret.json",
+      VAULT_SECRET_PATH      = "secret/myapp/config",
       VAULT_ASSUMED_ROLE_ARN = var.assume_role ? aws_iam_role.extra_role[0].arn : "",
-      VAULT_RUN_MODE       = "default",
-      DATABASE_URL         = aws_db_instance.main.address
+      VAULT_RUN_MODE         = "default",
+      VAULT_LOG_LEVEL        = "debug",
+      DATABASE_URL           = aws_db_instance.main.address
     }
   }
 }
 
 // if you have built a local version you want to use
 resource "aws_lambda_layer_version" "vle" {
-  count = var.local_extension ? 1 : 0
-  filename = "../../pkg/vault-lambda-extension.zip"
-  layer_name = "vault-lambda-extension"
+  count                    = var.local_extension ? 1 : 0
+  filename                 = "../../pkg/vault-lambda-extension.zip"
+  layer_name               = "vault-lambda-extension"
   compatible_architectures = ["x86_64"]
 }