fix(server): use default backend logger, stream logs to the vault server

e2e/go.mod

@@ -4,6 +4,7 @@ go 1.15
 
 require (
 	github.com/Masterminds/goutils v1.1.1
+	github.com/hashicorp/go-hclog v0.16.1 // indirect
 	github.com/hashicorp/vault/sdk v0.2.1
 	github.com/onsi/ginkgo v1.16.4
 	github.com/onsi/gomega v1.16.0

e2e/tests/flow/complete_cycle_test.go

@@ -11,6 +11,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault/sdk/logical"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
@@ -40,7 +41,7 @@ var _ = Describe("Complete cycle", func() {
 
 	serverInitVariables := func() {
 		var err error
-		backend, err = server.NewBackend()
+		backend, err = server.NewBackend(hclog.L())
 		Ω(err).ShouldNot(HaveOccurred())
 		storage = &logical.InmemStorage{}
 

server/.gitignore

@@ -1,6 +1,5 @@
 # Runtime
 /vault
 /publisher
-/trdl.log
 /.minio_data
 /.run

server/Makefile

@@ -28,9 +28,6 @@ vault/plugins/vault-plugin-secrets-trdl: $(GOSRC)
 build: vault/plugins/vault-plugin-secrets-trdl
 
 .run: vault/plugins/vault-plugin-secrets-trdl
-	rm -f trdl.log
-	touch trdl.log
-
 	# Run minio, create bucket
 	docker rm -f trdl_dev_minio || true
 	docker run --rm --volume $$(pwd):/wrk alpine rm -rf /wrk/.minio_data
@@ -77,14 +74,13 @@ build: vault/plugins/vault-plugin-secrets-trdl
 	touch .run
 
 tail:
-	tail -f trdl.log
+	docker logs -f trdl_dev_vault
 
 clean:
 	rm -f ./vault/plugins/vault-plugin-secrets-trdl
 	docker rm -f trdl_dev_minio || true
 	docker rm -f trdl_dev_vault || true
 	docker run --rm --volume $$(pwd):/wrk alpine rm -rf /wrk/.minio_data
-	rm -f trdl.log
 
 install-to-dev: build
 	: "$${TRDL_DEV_SSH_HOST:?not set}"

server/backend.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 
+	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault/sdk/framework"
 	"github.com/hashicorp/vault/sdk/logical"
 
@@ -32,7 +33,7 @@ type Backend struct {
 var _ logical.Factory = Factory
 
 func Factory(ctx context.Context, conf *logical.BackendConfig) (logical.Backend, error) {
-	b, err := NewBackend()
+	b, err := NewBackend(conf.Logger)
 	if err != nil {
 		return nil, err
 	}
@@ -48,9 +49,9 @@ func Factory(ctx context.Context, conf *logical.BackendConfig) (logical.Backend,
 	return b, nil
 }
 
-func NewBackend() (*Backend, error) {
-	tasksManager := tasks_manager.NewManager()
-	publisherManager := publisher.NewPublisher()
+func NewBackend(logger hclog.Logger) (*Backend, error) {
+	tasksManager := tasks_manager.NewManager(logger)
+	publisherManager := publisher.NewPublisher(logger)
 
 	b := &Backend{
 		TasksManager: tasksManager,

server/cmd/vault-plugin-secrets-trdl/main.go

@@ -1,7 +1,6 @@
 package main
 
 import (
-	"fmt"
 	"net"
 	"net/http"
 	_ "net/http/pprof"
@@ -22,19 +21,6 @@ func main() {
 		IncludeLocation: true,
 	}
 
-	var logFilePath string
-	if v := os.Getenv("VAULT_PLUGIN_SECRETS_TRDL_LOG_FILE"); v != "" {
-		logFilePath = v
-	} else {
-		logFilePath = "trdl.log"
-	}
-
-	logFile, err := os.OpenFile(logFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o666)
-	if err != nil {
-		panic(fmt.Sprintf("failed to open trdl.log file: %s", err))
-	}
-	hclogOpts.Output = logFile
-
 	if util.IsEnvVarTrue("VAULT_PLUGIN_SECRETS_TRDL_DEBUG") {
 		hclogOpts.Level = hclog.Trace
 
@@ -60,25 +46,23 @@ func main() {
 	tlsProviderFunc := api.VaultPluginTLSProvider(tlsConfig)
 
 	if err := plugin.Serve(&plugin.ServeOpts{
-		Logger:             hclog.Default(),
 		BackendFactoryFunc: trdl.Factory,
 		TLSProviderFunc:    tlsProviderFunc,
 	}); err != nil {
-		hclog.L().Error("plugin shutting down", "error", err)
 		os.Exit(1)
 	}
 }
 
 func servePprof() {
 	listener, err := net.Listen("tcp", "127.0.0.1:0")
 	if err != nil {
-		hclog.L().Warn(fmt.Sprintf("can't serve pprof: %s", err))
+		// hclog.L().Warn(fmt.Sprintf("can't serve pprof: %s", err))
 		return
 	}
 
-	hclog.L().Info(fmt.Sprintf("pprof for PID %d will be available on http://127.0.0.1:%d/debug/pprof", os.Getpid(), listener.Addr().(*net.TCPAddr).Port))
+	// hclog.L().Info(fmt.Sprintf("pprof for PID %d will be available on http://127.0.0.1:%d/debug/pprof", os.Getpid(), listener.Addr().(*net.TCPAddr).Port))
 	if err := http.Serve(listener, nil); err != nil {
-		hclog.L().Warn(fmt.Sprintf("can't serve pprof: %s", err))
+		// hclog.L().Warn(fmt.Sprintf("can't serve pprof: %s", err))
 		return
 	}
 }

server/path_publish.go

@@ -107,10 +107,10 @@ func (b *Backend) pathPublish(ctx context.Context, req *logical.Request, fields
 
 	taskUUID, err := b.TasksManager.RunTask(context.Background(), req.Storage, func(ctx context.Context, storage logical.Storage) error {
 		logboek.Context(ctx).Default().LogF("Started task\n")
-		hclog.L().Debug("Started task")
+		b.Logger().Debug("Started task")
 
 		logboek.Context(ctx).Default().LogF("Cloning git repo\n")
-		hclog.L().Debug("Cloning git repo")
+		b.Logger().Debug("Cloning git repo")
 
 		gitBranch := cfg.GitTrdlChannelsBranch
 		gitRepo, err := cloneGitRepositoryBranch(cfg.GitRepoUrl, gitBranch, gitUsername, gitPassword)
@@ -126,14 +126,14 @@ func (b *Backend) pathPublish(ctx context.Context, req *logical.Request, fields
 
 		if lastPublishedGitCommit == headCommit {
 			logboek.Context(ctx).Default().LogF("Head commit %q not changed: skipping publish task\n", headCommit)
-			hclog.L().Debug(fmt.Sprintf("Head commit %q not changed: skipping publish task", headCommit))
+			b.Logger().Debug(fmt.Sprintf("Head commit %q not changed: skipping publish task", headCommit))
 
 			return nil
 		}
 
 		if lastPublishedGitCommit != "" {
 			logboek.Context(ctx).Default().LogF("Checking previously published commit %q is ancestor to the current head commit %q\n", lastPublishedGitCommit, headCommit)
-			hclog.L().Debug(fmt.Sprintf("Checking previously published commit %q is ancestor to the current head commit %q", lastPublishedGitCommit, headCommit))
+			b.Logger().Debug(fmt.Sprintf("Checking previously published commit %q is ancestor to the current head commit %q", lastPublishedGitCommit, headCommit))
 
 			isAncestor, err := trdlGit.IsAncestor(gitRepo, lastPublishedGitCommit, headRef.Hash().String())
 			if err != nil {
@@ -146,7 +146,7 @@ func (b *Backend) pathPublish(ctx context.Context, req *logical.Request, fields
 		}
 
 		logboek.Context(ctx).Default().LogF("Verifying tag PGP signatures of the commit %q\n", headCommit)
-		hclog.L().Debug(fmt.Sprintf("Verifying tag PGP signatures of the commit %q", headCommit))
+		b.Logger().Debug(fmt.Sprintf("Verifying tag PGP signatures of the commit %q", headCommit))
 
 		trustedPGPPublicKeys, err := pgp.GetTrustedPGPPublicKeys(ctx, req.Storage)
 		if err != nil {
@@ -158,10 +158,10 @@ func (b *Backend) pathPublish(ctx context.Context, req *logical.Request, fields
 		}
 
 		logboek.Context(ctx).Default().LogF("Verified commit signatures\n")
-		hclog.L().Debug("Verified commit signatures")
+		b.Logger().Debug("Verified commit signatures")
 
 		logboek.Context(ctx).Default().LogF("Getting trdl_channels.yaml configuration from the commit %q\n", headCommit)
-		hclog.L().Debug(fmt.Sprintf("Getting trdl_channels.yaml configuration from the commit %q\n", headCommit))
+		b.Logger().Debug(fmt.Sprintf("Getting trdl_channels.yaml configuration from the commit %q\n", headCommit))
 
 		cfg, err := GetTrdlChannelsConfig(gitRepo)
 		if err != nil {
@@ -170,34 +170,34 @@ func (b *Backend) pathPublish(ctx context.Context, req *logical.Request, fields
 
 		cfgDump, _ := yaml.Marshal(cfg)
 		logboek.Context(ctx).Default().LogF("Got trdl channels config:\n%s\n---\n", cfgDump)
-		hclog.L().Debug(fmt.Sprintf("Got trdl channels config:\n%s\n---", cfgDump))
+		b.Logger().Debug(fmt.Sprintf("Got trdl channels config:\n%s\n---", cfgDump))
 
-		if err := ValidatePublishConfig(ctx, b.Publisher, publisherRepository, cfg); err != nil {
+		if err := ValidatePublishConfig(ctx, b.Publisher, publisherRepository, cfg, b.Logger()); err != nil {
 			return fmt.Errorf("unable to publish bad config: %s", err)
 		}
 
 		logboek.Context(ctx).Default().LogF("Publishing trdl channels config into the TUF repository\n")
-		hclog.L().Debug("Publishing trdl channels config into the TUF repository")
+		b.Logger().Debug("Publishing trdl channels config into the TUF repository")
 		if err := b.Publisher.StageChannelsConfig(ctx, publisherRepository, cfg); err != nil {
 			return fmt.Errorf("error publishing trdl channels into the repository: %s", err)
 		}
 
 		logboek.Context(ctx).Default().LogF("Committing TUF repository state\n")
-		hclog.L().Debug("Committing TUF repository state")
+		b.Logger().Debug("Committing TUF repository state")
 
 		if err := publisherRepository.CommitStaged(ctx); err != nil {
 			return fmt.Errorf("unable to commit new tuf repository state: %s", err)
 		}
 
 		logboek.Context(ctx).Default().LogF("Storing published commit record %q into the storage\n", headCommit)
-		hclog.L().Debug(fmt.Sprintf("Storing published commit record %q into the storage", headCommit))
+		b.Logger().Debug(fmt.Sprintf("Storing published commit record %q into the storage", headCommit))
 
 		if err := storage.Put(ctx, &logical.StorageEntry{Key: storageKeyLastPublishedGitCommit, Value: []byte(headCommit)}); err != nil {
 			return fmt.Errorf("unable to put %q into storage: %s", storageKeyLastPublishedGitCommit, err)
 		}
 
 		logboek.Context(ctx).Default().LogF("Task finished\n")
-		hclog.L().Debug("Task finished")
+		b.Logger().Debug("Task finished")
 
 		return nil
 	})
@@ -220,14 +220,14 @@ func (b *Backend) pathPublish(ctx context.Context, req *logical.Request, fields
 	}, nil
 }
 
-func ValidatePublishConfig(ctx context.Context, publisher publisher.Interface, publisherRepository publisher.RepositoryInterface, config *config.TrdlChannels) error {
+func ValidatePublishConfig(ctx context.Context, publisher publisher.Interface, publisherRepository publisher.RepositoryInterface, config *config.TrdlChannels, logger hclog.Logger) error {
 	existingReleases, err := publisher.GetExistingReleases(ctx, publisherRepository)
 	if err != nil {
 		return fmt.Errorf("error getting existing targets: %s", err)
 	}
 
 	logboek.Context(ctx).Default().LogF("Got existing releases list: %v\n", existingReleases)
-	hclog.L().Debug(fmt.Sprintf("Got existing releases list: %v\n", existingReleases))
+	logger.Debug(fmt.Sprintf("Got existing releases list: %v\n", existingReleases))
 
 	var nonExistingReleases []string
 

server/path_release.go

@@ -120,18 +120,18 @@ func (b *Backend) pathRelease(ctx context.Context, req *logical.Request, fields
 
 	taskUUID, err := b.TasksManager.RunTask(context.Background(), req.Storage, func(ctx context.Context, storage logical.Storage) error {
 		logboek.Context(ctx).Default().LogF("Started task\n")
-		hclog.L().Debug("Started task")
+		b.Logger().Debug("Started task")
 
 		logboek.Context(ctx).Default().LogF("Cloning git repo\n")
-		hclog.L().Debug("Cloning git repo")
+		b.Logger().Debug("Cloning git repo")
 
 		gitRepo, err := cloneGitRepositoryTag(cfg.GitRepoUrl, gitTag, gitUsername, gitPassword)
 		if err != nil {
 			return fmt.Errorf("unable to clone git repository: %s", err)
 		}
 
 		logboek.Context(ctx).Default().LogF("Verifying tag PGP signatures of the git tag %q\n", gitTag)
-		hclog.L().Debug("Verifying tag PGP signatures of the git tag %q", gitTag)
+		b.Logger().Debug("Verifying tag PGP signatures of the git tag %q", gitTag)
 
 		trustedPGPPublicKeys, err := pgp.GetTrustedPGPPublicKeys(ctx, req.Storage)
 		if err != nil {
@@ -143,26 +143,26 @@ func (b *Backend) pathRelease(ctx context.Context, req *logical.Request, fields
 		}
 
 		logboek.Context(ctx).Default().LogF("Getting trdl.yaml configuration from the git tag %q\n", gitTag)
-		hclog.L().Debug(fmt.Sprintf("Getting trdl.yaml configuration from the git tag %q\n", gitTag))
+		b.Logger().Debug(fmt.Sprintf("Getting trdl.yaml configuration from the git tag %q\n", gitTag))
 
 		trdlCfg, err := getTrdlConfig(gitRepo, gitTag)
 		if err != nil {
 			return fmt.Errorf("unable to get trdl configuration: %s", err)
 		}
 
 		logboek.Context(ctx).Default().LogF("Starting release artifacts tar archive build\n")
-		hclog.L().Debug("Starting release artifacts tar archive build")
+		b.Logger().Debug("Starting release artifacts tar archive build")
 
 		tarBuf := buffer.New(64 * 1024 * 1024)
 		tarReader, tarWriter := nio.Pipe(tarBuf)
 
-		err, cleanupFunc := buildReleaseArtifacts(ctx, tarWriter, gitRepo, trdlCfg.DockerImage, trdlCfg.Commands)
+		err, cleanupFunc := buildReleaseArtifacts(ctx, tarWriter, gitRepo, trdlCfg.DockerImage, trdlCfg.Commands, b.Logger())
 		if err != nil {
 			return fmt.Errorf("unable to build release artifacts: %s", err)
 		}
 		defer func() {
 			if err := cleanupFunc(); err != nil {
-				hclog.L().Error(fmt.Sprintf("unable to remove service docker image: %s", err))
+				b.Logger().Error(fmt.Sprintf("unable to remove service docker image: %s", err))
 			}
 		}()
 
@@ -181,7 +181,7 @@ func (b *Backend) pathRelease(ctx context.Context, req *logical.Request, fields
 
 				if hdr.Typeflag != tar.TypeDir {
 					logboek.Context(ctx).Default().LogF("Publishing %q into the tuf repo ...\n", hdr.Name)
-					hclog.L().Debug(fmt.Sprintf("Publishing %q into the tuf repo ...", hdr.Name))
+					b.Logger().Debug(fmt.Sprintf("Publishing %q into the tuf repo ...", hdr.Name))
 
 					if err := b.Publisher.StageReleaseTarget(ctx, publisherRepository, releaseName, hdr.Name, twArtifacts); err != nil {
 						return fmt.Errorf("unable to publish release target %q: %s", hdr.Name, err)
@@ -190,15 +190,15 @@ func (b *Backend) pathRelease(ctx context.Context, req *logical.Request, fields
 			}
 
 			logboek.Context(ctx).Default().LogF("Committing TUF repository state\n")
-			hclog.L().Debug("Committing TUF repository state")
+			b.Logger().Debug("Committing TUF repository state")
 
 			if err := publisherRepository.CommitStaged(ctx); err != nil {
 				return fmt.Errorf("unable to commit new tuf repository state: %s", err)
 			}
 		}
 
 		logboek.Context(ctx).Default().LogF("Task finished\n")
-		hclog.L().Debug("Task finished")
+		b.Logger().Debug("Task finished")
 
 		return nil
 	})
@@ -260,7 +260,7 @@ func getTrdlConfig(gitRepo *git.Repository, gitTag string) (*config.Trdl, error)
 	return cfg, nil
 }
 
-func buildReleaseArtifacts(ctx context.Context, tarWriter *nio.PipeWriter, gitRepo *git.Repository, fromImage string, runCommands []string) (error, func() error) {
+func buildReleaseArtifacts(ctx context.Context, tarWriter *nio.PipeWriter, gitRepo *git.Repository, fromImage string, runCommands []string, logger hclog.Logger) (error, func() error) {
 	cli, err := client.NewClientWithOpts(client.FromEnv, client.WithAPIVersionNegotiation())
 	if err != nil {
 		return fmt.Errorf("unable to create docker client: %s", err), nil
@@ -280,7 +280,7 @@ func buildReleaseArtifacts(ctx context.Context, tarWriter *nio.PipeWriter, gitRe
 			tw := tar.NewWriter(contextWriter)
 
 			logboek.Context(ctx).Default().LogF("Adding git worktree files to the build context\n")
-			hclog.L().Debug("Adding git worktree files to the build context")
+			logger.Debug("Adding git worktree files to the build context")
 
 			if err := trdlGit.AddWorktreeFilesToTar(tw, gitRepo); err != nil {
 				return fmt.Errorf("unable to add git worktree files to tar: %s", err)
@@ -312,7 +312,7 @@ func buildReleaseArtifacts(ctx context.Context, tarWriter *nio.PipeWriter, gitRe
 	}()
 
 	logboek.Context(ctx).Default().LogF("Building docker image with artifacts\n")
-	hclog.L().Debug("Building docker image with artifacts")
+	logger.Debug("Building docker image with artifacts")
 
 	response, err := cli.ImageBuild(ctx, contextReader, types.ImageBuildOptions{
 		Dockerfile:  serviceDockerfilePathInContext,