Fix garage Wait method not sleeping properly between tries

I switched to using mlog for logging, as opposed to writing directly to
Stderr. This gives us control over log levels, as well as coordination
so that we don't have multiple go-routines writing to stderr at the same
time.

entrypoint/default.nix

@@ -7,7 +7,7 @@
   pname = "cryptic-net-entrypoint";
   version = "unstable";
   src = ./src;
-  vendorSha256 = "sha256-1mHD0tmITlGjeo6F+Dvd2TdEPzxWtndy/J+uGHWKen4=";
+  vendorSha256 = "sha256-TTTXwztv4xwF1uXcYoSka6HwgHwU1AnClF4fguXVtK4=";
   subPackages = [
     "cmd/entrypoint"
   ];

entrypoint/src/bootstrap/garage_global_bucket.go

@@ -6,10 +6,11 @@ import (
 	"cryptic-net/garage"
 	"cryptic-net/nebula"
 	"fmt"
-	"os"
 	"path/filepath"
 	"strings"
 
+	"github.com/mediocregopher/mediocre-go-lib/v2/mctx"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 	"github.com/minio/minio-go/v7"
 	"gopkg.in/yaml.v3"
 )
@@ -85,6 +86,7 @@ func RemoveGarageBootstrapHost(
 // stored in garage.
 func (b Bootstrap) GetGarageBootstrapHosts(
 	ctx context.Context,
+	logger *mlog.Logger,
 ) (
 	map[string]Host, error,
 ) {
@@ -103,6 +105,8 @@ func (b Bootstrap) GetGarageBootstrapHosts(
 
 	for objInfo := range objInfoCh {
 
+		ctx := mctx.Annotate(ctx, "object-key", objInfo.Key)
+
 		if objInfo.Err != nil {
 			return nil, fmt.Errorf("listing objects: %w", objInfo.Err)
 		}
@@ -132,7 +136,7 @@ func (b Bootstrap) GetGarageBootstrapHosts(
 		)
 
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "unwrapping signed public creds for %q: %v\n", objInfo.Key, err)
+			logger.Warn(ctx, "unwrapping signed public creds", err)
 			continue
 		}
 
@@ -143,20 +147,20 @@ func (b Bootstrap) GetGarageBootstrapHosts(
 		)
 
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "invalid signed public creds for %q: %v\n", objInfo.Key, err)
+			logger.Warn(ctx, "invalid signed public creds", err)
 			continue
 		}
 
 		var hostPublicCreds nebula.HostPublicCredentials
 		if err := yaml.Unmarshal(hostPublicCredsB, &hostPublicCreds); err != nil {
-			fmt.Fprintf(os.Stderr, "yaml unmarshaling signed public creds for %q: %v\n", objInfo.Key, err)
+			logger.Warn(ctx, "yaml unmarshaling signed public creds", err)
 			continue
 		}
 
 		err = nebula.ValidateSignature(hostPublicCreds.SigningKeyPEM, hostB, hostSig)
 
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "invalid host data for %q: %v\n", objInfo.Key, err)
+			logger.Warn(ctx, "invalid host data", err)
 			continue
 		}
 

entrypoint/src/cmd/entrypoint/admin.go

@@ -16,6 +16,7 @@ import (
 	"strings"
 
 	"code.betamike.com/cryptic-io/pmux/pmuxlib"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 )
 
 func randStr(l int) string {
@@ -84,10 +85,17 @@ var subCmdAdminCreateNetwork = subCmd{
 			"Name of this host, which will be the first host in the network",
 		)
 
+		logLevelStr := flags.StringP(
+			"log-level", "l", "info",
+			`Maximum log level which should be output. Values can be "debug", "info", "warn", "error", "fatal". Does not apply to sub-processes`,
+		)
+
 		if err := flags.Parse(subCmdCtx.args); err != nil {
 			return fmt.Errorf("parsing flags: %w", err)
 		}
 
+		ctx := subCmdCtx.ctx
+
 		if *dumpConfig {
 			return daemon.CopyDefaultConfig(os.Stdout, envAppDirPath)
 		}
@@ -96,6 +104,13 @@ var subCmdAdminCreateNetwork = subCmd{
 			return errors.New("--name, --domain, --ip-net, and --hostname are required")
 		}
 
+		logLevel := mlog.LevelFromString(*logLevelStr)
+		if logLevel == nil {
+			return fmt.Errorf("couldn't parse log level %q", *logLevelStr)
+		}
+
+		logger := subCmdCtx.logger.WithMaxLevel(logLevel.Int())
+
 		*domain = strings.TrimRight(strings.TrimLeft(*domain, "."), ".")
 
 		ip, subnet, err := net.ParseCIDR(*ipNetStr)
@@ -107,7 +122,7 @@ var subCmdAdminCreateNetwork = subCmd{
 			return fmt.Errorf("invalid hostname %q: %w", *hostName, err)
 		}
 
-		runtimeDirCleanup, err := setupAndLockRuntimeDir()
+		runtimeDirCleanup, err := setupAndLockRuntimeDir(ctx, logger)
 		if err != nil {
 			return fmt.Errorf("setting up runtime directory: %w", err)
 		}
@@ -191,10 +206,10 @@ var subCmdAdminCreateNetwork = subCmd{
 			),
 		}
 
-		ctx, cancel := context.WithCancel(subCmdCtx.ctx)
+		ctx, cancel := context.WithCancel(ctx)
 		pmuxDoneCh := make(chan struct{})
 
-		fmt.Fprintln(os.Stderr, "starting child processes")
+		logger.Info(ctx, "starting child processes")
 		go func() {
 			// NOTE both stdout and stderr are sent to stderr, so that the user
 			// can pipe the resulting admin.yml to stdout.
@@ -204,22 +219,22 @@ var subCmdAdminCreateNetwork = subCmd{
 
 		defer func() {
 			cancel()
-			fmt.Fprintln(os.Stderr, "waiting for child processes to exit")
+			logger.Info(ctx, "waiting for child processes to exit")
 			<-pmuxDoneCh
 		}()
 
-		fmt.Fprintln(os.Stderr, "waiting for garage instances to come online")
-		if err := waitForGarageAndNebula(ctx, hostBootstrap, daemonConfig); err != nil {
+		logger.Info(ctx, "waiting for garage instances to come online")
+		if err := waitForGarageAndNebula(ctx, logger, hostBootstrap, daemonConfig); err != nil {
 			return fmt.Errorf("waiting for garage to start up: %w", err)
 		}
 
-		fmt.Fprintln(os.Stderr, "applying initial garage layout")
-		if err := garageApplyLayout(ctx, hostBootstrap, daemonConfig); err != nil {
+		logger.Info(ctx, "applying initial garage layout")
+		if err := garageApplyLayout(ctx, logger, hostBootstrap, daemonConfig); err != nil {
 			return fmt.Errorf("applying initial garage layout: %w", err)
 		}
 
-		fmt.Fprintln(os.Stderr, "initializing garage shared global bucket")
-		err = garageInitializeGlobalBucket(ctx, hostBootstrap, daemonConfig)
+		logger.Info(ctx, "initializing garage shared global bucket")
+		err = garageInitializeGlobalBucket(ctx, logger, hostBootstrap, daemonConfig)
 
 		if cErr := (garage.AdminClientError{}); errors.As(err, &cErr) && cErr.StatusCode == 409 {
 			return fmt.Errorf("shared global bucket has already been created, are the storage allocations from a previously initialized cryptic-net being used?")
@@ -228,7 +243,7 @@ var subCmdAdminCreateNetwork = subCmd{
 			return fmt.Errorf("initializing garage shared global bucket: %w", err)
 		}
 
-		fmt.Fprintln(os.Stderr, "cluster initialized successfully, writing admin.yml to stdout")
+		logger.Info(ctx, "cluster initialized successfully, writing admin.yml to stdout")
 
 		adm := admin.Admin{
 			CreationParams: adminCreationParams,

entrypoint/src/cmd/entrypoint/daemon.go

@@ -14,6 +14,8 @@ import (
 	"cryptic-net/daemon"
 
 	"code.betamike.com/cryptic-io/pmux/pmuxlib"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mctx"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 )
 
 // The daemon sub-command deals with starting an actual cryptic-net daemon
@@ -40,6 +42,7 @@ import (
 // is overwritten and true is returned.
 func reloadBootstrap(
 	ctx context.Context,
+	logger *mlog.Logger,
 	hostBootstrap bootstrap.Bootstrap,
 ) (
 	bootstrap.Bootstrap, bool, error,
@@ -47,7 +50,7 @@ func reloadBootstrap(
 
 	thisHost := hostBootstrap.ThisHost()
 
-	newHosts, err := hostBootstrap.GetGarageBootstrapHosts(ctx)
+	newHosts, err := hostBootstrap.GetGarageBootstrapHosts(ctx, logger)
 	if err != nil {
 		return bootstrap.Bootstrap{}, false, fmt.Errorf("getting hosts from garage: %w", err)
 	}
@@ -85,6 +88,7 @@ func reloadBootstrap(
 // updated boostrap info.
 func runDaemonPmuxOnce(
 	ctx context.Context,
+	logger *mlog.Logger,
 	hostBootstrap bootstrap.Bootstrap,
 	daemonConfig daemon.Config,
 ) (
@@ -116,8 +120,6 @@ func runDaemonPmuxOnce(
 		),
 	}
 
-	doneCh := ctx.Done()
-
 	var wg sync.WaitGroup
 	defer wg.Wait()
 
@@ -130,18 +132,28 @@ func runDaemonPmuxOnce(
 		pmuxlib.Run(ctx, os.Stdout, os.Stderr, pmuxConfig)
 	}()
 
-	wg.Add(1)
-	go func() {
-		defer wg.Done()
+	if err := waitForGarageAndNebula(ctx, logger, hostBootstrap, daemonConfig); err != nil {
+		return bootstrap.Bootstrap{}, fmt.Errorf("waiting for nebula/garage to start up: %w", err)
+	}
 
-		if err := waitForGarageAndNebula(ctx, hostBootstrap, daemonConfig); err != nil {
-			fmt.Fprintf(os.Stderr, "aborted waiting for garage instances to be accessible: %v\n", err)
-			return
+	err = doOnce(ctx, func(ctx context.Context) error {
+		if err := hostBootstrap.PutGarageBoostrapHost(ctx); err != nil {
+			logger.Error(ctx, "updating host info in garage", err)
+			return err
 		}
 
+		return nil
+	})
+
+	if err != nil {
+		return bootstrap.Bootstrap{}, fmt.Errorf("updating host info in garage: %w", err)
+	}
+
+	if len(daemonConfig.Storage.Allocations) > 0 {
+
 		err := doOnce(ctx, func(ctx context.Context) error {
-			if err := hostBootstrap.PutGarageBoostrapHost(ctx); err != nil {
-				fmt.Fprintf(os.Stderr, "updating host info in garage: %v\n", err)
+			if err := garageApplyLayout(ctx, logger, hostBootstrap, daemonConfig); err != nil {
+				logger.Error(ctx, "applying garage layout", err)
 				return err
 			}
 
@@ -149,33 +161,8 @@ func runDaemonPmuxOnce(
 		})
 
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "aborted updating host info in garage: %v\n", err)
+			return bootstrap.Bootstrap{}, fmt.Errorf("applying garage layout: %w", err)
 		}
-	}()
-
-	if len(daemonConfig.Storage.Allocations) > 0 {
-		wg.Add(1)
-		go func() {
-			defer wg.Done()
-
-			if err := waitForGarageAndNebula(ctx, hostBootstrap, daemonConfig); err != nil {
-				fmt.Fprintf(os.Stderr, "aborted waiting for garage instances to be accessible: %v\n", err)
-				return
-			}
-
-			err := doOnce(ctx, func(ctx context.Context) error {
-				if err := garageApplyLayout(ctx, hostBootstrap, daemonConfig); err != nil {
-					fmt.Fprintf(os.Stderr, "applying garage layout: %v\n", err)
-					return err
-				}
-
-				return nil
-			})
-
-			if err != nil {
-				fmt.Fprintf(os.Stderr, "aborted applying garage layout: %v\n", err)
-			}
-		}()
 	}
 
 	ticker := time.NewTicker(3 * time.Minute)
@@ -184,7 +171,7 @@ func runDaemonPmuxOnce(
 	for {
 		select {
 
-		case <-doneCh:
+		case <-ctx.Done():
 			return bootstrap.Bootstrap{}, ctx.Err()
 
 		case <-ticker.C:
@@ -196,7 +183,7 @@ func runDaemonPmuxOnce(
 				err     error
 			)
 
-			if hostBootstrap, changed, err = reloadBootstrap(ctx, hostBootstrap); err != nil {
+			if hostBootstrap, changed, err = reloadBootstrap(ctx, logger, hostBootstrap); err != nil {
 				return bootstrap.Bootstrap{}, fmt.Errorf("reloading bootstrap: %w", err)
 
 			} else if changed {
@@ -229,15 +216,29 @@ var subCmdDaemon = subCmd{
 			`Path to a bootstrap.yml file. This only needs to be provided the first time the daemon is started, after that it is ignored. If the cryptic-net binary has a bootstrap built into it then this argument is always optional.`,
 		)
 
+		logLevelStr := flags.StringP(
+			"log-level", "l", "info",
+			`Maximum log level which should be output. Values can be "debug", "info", "warn", "error", "fatal". Does not apply to sub-processes`,
+		)
+
 		if err := flags.Parse(subCmdCtx.args); err != nil {
 			return fmt.Errorf("parsing flags: %w", err)
 		}
 
+		ctx := subCmdCtx.ctx
+
 		if *dumpConfig {
 			return daemon.CopyDefaultConfig(os.Stdout, envAppDirPath)
 		}
 
-		runtimeDirCleanup, err := setupAndLockRuntimeDir()
+		logLevel := mlog.LevelFromString(*logLevelStr)
+		if logLevel == nil {
+			return fmt.Errorf("couldn't parse log level %q", *logLevelStr)
+		}
+
+		logger := subCmdCtx.logger.WithMaxLevel(logLevel.Int())
+
+		runtimeDirCleanup, err := setupAndLockRuntimeDir(ctx, logger)
 		if err != nil {
 			return fmt.Errorf("setting up runtime directory: %w", err)
 		}
@@ -266,7 +267,11 @@ var subCmdDaemon = subCmd{
 				return false
 			}
 
-			fmt.Fprintf(os.Stderr, "bootstrap file found at %q\n", path)
+			logger.Info(
+				mctx.Annotate(ctx, "bootstrap-file-path", path),
+				"bootstrap file found",
+			)
+
 			hostBootstrapPath = path
 			return true
 		}
@@ -306,7 +311,7 @@ var subCmdDaemon = subCmd{
 
 		for {
 
-			hostBootstrap, err = runDaemonPmuxOnce(subCmdCtx.ctx, hostBootstrap, daemonConfig)
+			hostBootstrap, err = runDaemonPmuxOnce(ctx, logger, hostBootstrap, daemonConfig)
 
 			if errors.Is(err, context.Canceled) {
 				return nil

entrypoint/src/cmd/entrypoint/daemon_util.go

@@ -58,6 +58,6 @@ func doOnce(ctx context.Context, fn func(context.Context) error) error {
 			return ctxErr
 		}
 
-		time.Sleep(250 * time.Millisecond)
+		time.Sleep(1 * time.Second)
 	}
 }

entrypoint/src/cmd/entrypoint/garage_util.go

@@ -11,12 +11,19 @@ import (
 	"strconv"
 
 	"code.betamike.com/cryptic-io/pmux/pmuxlib"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 )
 
+func garageAdminClientLogger(logger *mlog.Logger) *mlog.Logger {
+	return logger.WithNamespace("garage-admin-client")
+}
+
 // newGarageAdminClient will return an AdminClient for a local garage instance,
 // or it will _panic_ if there is no local instance configured.
 func newGarageAdminClient(
-	hostBootstrap bootstrap.Bootstrap, daemonConfig daemon.Config,
+	logger *mlog.Logger,
+	hostBootstrap bootstrap.Bootstrap,
+	daemonConfig daemon.Config,
 ) *garage.AdminClient {
 
 	thisHost := hostBootstrap.ThisHost()
@@ -27,23 +34,31 @@ func newGarageAdminClient(
 			strconv.Itoa(daemonConfig.Storage.Allocations[0].AdminPort),
 		),
 		hostBootstrap.Garage.AdminToken,
+		garageAdminClientLogger(logger),
 	)
 }
 
 func waitForGarageAndNebula(
 	ctx context.Context,
+	logger *mlog.Logger,
 	hostBootstrap bootstrap.Bootstrap,
 	daemonConfig daemon.Config,
 ) error {
 
+	if err := waitForNebula(ctx, hostBootstrap); err != nil {
+		return fmt.Errorf("waiting for nebula to start: %w", err)
+	}
+
 	allocs := daemonConfig.Storage.Allocations
 
 	// if this host doesn't have any allocations specified then fall back to
 	// waiting for nebula
 	if len(allocs) == 0 {
-		return waitForNebula(ctx, hostBootstrap)
+		return nil
 	}
 
+	logger = garageAdminClientLogger(logger)
+
 	for _, alloc := range allocs {
 
 		adminAddr := net.JoinHostPort(
@@ -54,10 +69,11 @@ func waitForGarageAndNebula(
 		adminClient := garage.NewAdminClient(
 			adminAddr,
 			hostBootstrap.Garage.AdminToken,
+			logger,
 		)
 
 		if err := adminClient.Wait(ctx); err != nil {
-			return fmt.Errorf("waiting for instance %q to start up: %w", adminAddr, err)
+			return fmt.Errorf("waiting for garage instance %q to start up: %w", adminAddr, err)
 		}
 	}
 
@@ -161,12 +177,13 @@ func garagePmuxProcConfigs(
 
 func garageInitializeGlobalBucket(
 	ctx context.Context,
+	logger *mlog.Logger,
 	hostBootstrap bootstrap.Bootstrap,
 	daemonConfig daemon.Config,
 ) error {
 
 	var (
-		adminClient       = newGarageAdminClient(hostBootstrap, daemonConfig)
+		adminClient       = newGarageAdminClient(logger, hostBootstrap, daemonConfig)
 		globalBucketCreds = hostBootstrap.Garage.GlobalBucketS3APICredentials
 	)
 
@@ -223,12 +240,13 @@ func garageInitializeGlobalBucket(
 
 func garageApplyLayout(
 	ctx context.Context,
+	logger *mlog.Logger,
 	hostBootstrap bootstrap.Bootstrap,
 	daemonConfig daemon.Config,
 ) error {
 
 	var (
-		adminClient = newGarageAdminClient(hostBootstrap, daemonConfig)
+		adminClient = newGarageAdminClient(logger, hostBootstrap, daemonConfig)
 		thisHost    = hostBootstrap.ThisHost()
 		hostName    = thisHost.Name
 		allocs      = daemonConfig.Storage.Allocations

entrypoint/src/cmd/entrypoint/hosts.go

@@ -8,6 +8,7 @@ import (
 	"regexp"
 	"sort"
 
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 	"gopkg.in/yaml.v3"
 )
 
@@ -28,12 +29,32 @@ var subCmdHostsList = subCmd{
 	checkLock: true,
 	do: func(subCmdCtx subCmdCtx) error {
 
+		flags := subCmdCtx.flagSet(false)
+
+		logLevelStr := flags.StringP(
+			"log-level", "l", "info",
+			`Maximum log level which should be output. Values can be "debug", "info", "warn", "error", "fatal". Does not apply to sub-processes`,
+		)
+
+		if err := flags.Parse(subCmdCtx.args); err != nil {
+			return fmt.Errorf("parsing flags: %w", err)
+		}
+
+		ctx := subCmdCtx.ctx
+
+		logLevel := mlog.LevelFromString(*logLevelStr)
+		if logLevel == nil {
+			return fmt.Errorf("couldn't parse log level %q", *logLevelStr)
+		}
+
+		logger := subCmdCtx.logger.WithMaxLevel(logLevel.Int())
+
 		hostBootstrap, err := loadHostBootstrap()
 		if err != nil {
 			return fmt.Errorf("loading host bootstrap: %w", err)
 		}
 
-		hostsMap, err := hostBootstrap.GetGarageBootstrapHosts(subCmdCtx.ctx)
+		hostsMap, err := hostBootstrap.GetGarageBootstrapHosts(ctx, logger)
 		if err != nil {
 			return fmt.Errorf("retrieving hosts from garage: %w", err)
 		}

entrypoint/src/cmd/entrypoint/logger.go

@@ -0,0 +1,56 @@
+package main
+
+import (
+	"fmt"
+	"os"
+	"path"
+	"sync"
+
+	"github.com/mediocregopher/mediocre-go-lib/v2/mctx"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
+)
+
+type logMsgHandler struct {
+	stderr *os.File
+	l      sync.Mutex
+}
+
+func newLogMsgHandler() mlog.MessageHandler {
+	return &logMsgHandler{
+		stderr: os.Stderr,
+	}
+}
+
+func (h *logMsgHandler) Sync() error {
+	return h.stderr.Sync()
+}
+
+func (h *logMsgHandler) Handle(msg mlog.FullMessage) error {
+	h.l.Lock()
+	defer h.l.Unlock()
+
+	var namespaceStr string
+
+	if len(msg.Namespace) > 0 {
+		namespaceStr = "[" + path.Join(msg.Namespace...) + "] "
+	}
+
+	var annotationsStr string
+
+	if m := mctx.EvaluateAnnotations(msg.Context, nil).StringMap(); len(m) > 0 {
+
+		for k, v := range m {
+			annotationsStr += fmt.Sprintf(" %q=%q", k, v)
+		}
+	}
+
+	fmt.Fprintf(
+		h.stderr, "%s %s%s%s\n",
+		msg.Level.String(),
+		namespaceStr,
+		msg.Description,
+		annotationsStr,
+	)
+
+	return nil
+}

entrypoint/src/cmd/entrypoint/main.go

@@ -2,13 +2,14 @@ package main
 
 import (
 	"context"
-	"fmt"
 	"os"
 	"os/signal"
 	"path/filepath"
 	"syscall"
 
 	"github.com/adrg/xdg"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mctx"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 )
 
 // The purpose of this binary is to act as the entrypoint of the cryptic-net
@@ -32,6 +33,12 @@ var (
 
 func main() {
 
+	logger := mlog.NewLogger(&mlog.LoggerOpts{
+		MessageHandler: newLogMsgHandler(),
+		MaxLevel:       mlog.LevelInfo.Int(),
+	})
+	defer logger.Close()
+
 	ctx, cancel := context.WithCancel(context.Background())
 
 	signalCh := make(chan os.Signal, 2)
@@ -40,18 +47,20 @@ func main() {
 	go func() {
 		sig := <-signalCh
 		cancel()
-		fmt.Fprintf(os.Stderr, "got signal %v, will exit gracefully\n", sig)
+
+		ctx := mctx.Annotate(ctx, "signal", sig.String())
+		logger.Info(ctx, "got signal, exiting gracefully")
 
 		sig = <-signalCh
-		fmt.Fprintf(os.Stderr, "second interrupt signal %v received, force quitting, there may be zombie children left behind, good luck!\n", sig)
 
-		os.Stderr.Sync()
-		os.Exit(1)
+		ctx = mctx.Annotate(ctx, "signal", sig.String())
+		logger.FatalString(ctx, "second signal received, force quitting, there may be zombie children left behind, good luck!")
 	}()
 
 	err := subCmdCtx{
-		args: os.Args[1:],
-		ctx:  ctx,
+		args:   os.Args[1:],
+		ctx:    ctx,
+		logger: logger,
 	}.doSubCmd(
 		subCmdAdmin,
 		subCmdDaemon,
@@ -61,6 +70,6 @@ func main() {
 	)
 
 	if err != nil {
-		panic(err)
+		logger.Fatal(ctx, "error running command", err)
 	}
 }

entrypoint/src/cmd/entrypoint/proc_lock.go

@@ -1,12 +1,15 @@
 package main
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"io/fs"
 	"os"
 	"path/filepath"
 
+	"github.com/mediocregopher/mediocre-go-lib/v2/mctx"
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 	"github.com/shirou/gopsutil/process"
 )
 
@@ -44,9 +47,10 @@ func writeLock() error {
 }
 
 // returns a cleanup function which will clean up the created runtime directory.
-func setupAndLockRuntimeDir() (func(), error) {
+func setupAndLockRuntimeDir(ctx context.Context, logger *mlog.Logger) (func(), error) {
 
-	fmt.Fprintf(os.Stderr, "will use runtime directory %q for temporary state\n", envRuntimeDirPath)
+	ctx = mctx.Annotate(ctx, "runtime-dir-path", envRuntimeDirPath)
+	logger.Info(ctx, "will use runtime directory for temporary state")
 
 	if err := os.MkdirAll(envRuntimeDirPath, 0700); err != nil {
 		return nil, fmt.Errorf("creating directory %q: %w", envRuntimeDirPath, err)
@@ -56,9 +60,9 @@ func setupAndLockRuntimeDir() (func(), error) {
 	}
 
 	return func() {
-		fmt.Fprintf(os.Stderr, "cleaning up runtime directory %q\n", envRuntimeDirPath)
+		logger.Info(ctx, "cleaning up runtime directory")
 		if err := os.RemoveAll(envRuntimeDirPath); err != nil {
-			fmt.Fprintf(os.Stderr, "error removing temporary directory %q: %v", envRuntimeDirPath, err)
+			logger.Error(ctx, "removing temporary directory", err)
 		}
 	}, nil
 }

entrypoint/src/cmd/entrypoint/sub_cmd.go

@@ -6,6 +6,7 @@ import (
 	"os"
 	"strings"
 
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 	"github.com/spf13/pflag"
 )
 
@@ -15,7 +16,8 @@ type subCmdCtx struct {
 	args        []string // command-line arguments, excluding the subCmd itself.
 	subCmdNames []string // names of subCmds so far, including this one
 
-	ctx context.Context
+	ctx    context.Context
+	logger *mlog.Logger
 }
 
 type subCmd struct {
@@ -110,6 +112,7 @@ func (ctx subCmdCtx) doSubCmd(subCmds ...subCmd) error {
 		args:        args,
 		subCmdNames: append(ctx.subCmdNames, subCmdName),
 		ctx:         ctx.ctx,
+		logger:      ctx.logger,
 	})
 
 	if err != nil {

entrypoint/src/garage/admin_client.go

@@ -7,7 +7,10 @@ import (
 	"fmt"
 	"io"
 	"net/http"
+	"net/http/httputil"
 	"time"
+
+	"github.com/mediocregopher/mediocre-go-lib/v2/mlog"
 )
 
 // AdminClientError gets returned from AdminClient's Do method for non-200
@@ -27,17 +30,21 @@ type AdminClient struct {
 	c          *http.Client
 	addr       string
 	adminToken string
+	logger     *mlog.Logger
 }
 
 // NewAdminClient initializes and returns an AdminClient which will use the
 // given address and adminToken for all requests made.
-func NewAdminClient(addr, adminToken string) *AdminClient {
+//
+// If Logger is nil then logs will be suppressed.
+func NewAdminClient(addr, adminToken string, logger *mlog.Logger) *AdminClient {
 	return &AdminClient{
 		c: &http.Client{
 			Transport: http.DefaultTransport.(*http.Transport).Clone(),
 		},
 		addr:       addr,
 		adminToken: adminToken,
+		logger:     logger,
 	}
 }
 
@@ -68,11 +75,31 @@ func (c *AdminClient) Do(
 
 	req.Header.Set("Authorization", "Bearer "+c.adminToken)
 
+	if c.logger.MaxLevel() >= mlog.LevelDebug.Int() {
+
+		reqB, err := httputil.DumpRequestOut(req, true)
+		if err != nil {
+			c.logger.Error(ctx, "failed to dump http request", err)
+		} else {
+			c.logger.Debug(ctx, "------ request ------\n"+string(reqB)+"\n")
+		}
+	}
+
 	res, err := c.c.Do(req)
 	if err != nil {
 		return fmt.Errorf("performing http request: %w", err)
 	}
 
+	if c.logger.MaxLevel() >= mlog.LevelDebug.Int() {
+
+		resB, err := httputil.DumpResponse(res, true)
+		if err != nil {
+			c.logger.Error(ctx, "failed to dump http response", err)
+		} else {
+			c.logger.Debug(ctx, "------ response ------\n"+string(resB)+"\n")
+		}
+	}
+
 	defer res.Body.Close()
 
 	if res.StatusCode != 200 {
@@ -103,7 +130,12 @@ func (c *AdminClient) Do(
 // ReplicationFactor-1 other garage instances. If the context is canceled it
 // will return the context error.
 func (c *AdminClient) Wait(ctx context.Context) error {
-	for {
+
+	for first := true; ; first = false {
+
+		if !first {
+			time.Sleep(250 * time.Millisecond)
+		}
 
 		var clusterStatus struct {
 			KnownNodes map[string]struct {
@@ -132,6 +164,5 @@ func (c *AdminClient) Wait(ctx context.Context) error {
 			return nil
 		}
 
-		time.Sleep(250 * time.Millisecond)
 	}
 }

entrypoint/src/go.mod

@@ -6,8 +6,8 @@ require (
 	code.betamike.com/cryptic-io/pmux v0.0.0-20221025185405-29241f144a2d
 	github.com/adrg/xdg v0.4.0
 	github.com/imdario/mergo v0.3.12
+	github.com/mediocregopher/mediocre-go-lib/v2 v2.0.0-beta.1.0.20221113151154-07f3889a705b
 	github.com/minio/minio-go/v7 v7.0.28
-	github.com/nlepage/go-tarfs v1.1.0
 	github.com/shirou/gopsutil v3.21.11+incompatible
 	github.com/slackhq/nebula v1.6.1
 	github.com/spf13/pflag v1.0.5

entrypoint/src/go.sum

@@ -1,5 +1,3 @@
-code.betamike.com/cryptic-io/pmux v0.0.0-20221020185531-7a7868003822 h1:c7Eu2h8gXOpOfhC1LvSYLNfiSsWTyvdI1XVpUuqMFHE=
-code.betamike.com/cryptic-io/pmux v0.0.0-20221020185531-7a7868003822/go.mod h1:cBuEN/rkaM/GH24uQroX/++qDmte+mLudDUqMt6XJWs=
 code.betamike.com/cryptic-io/pmux v0.0.0-20221025185405-29241f144a2d h1:s6nDTg23o9ujZZnl8ohZBDoG4SqPUyFfvod9DQjwmNU=
 code.betamike.com/cryptic-io/pmux v0.0.0-20221025185405-29241f144a2d/go.mod h1:cBuEN/rkaM/GH24uQroX/++qDmte+mLudDUqMt6XJWs=
 github.com/adrg/xdg v0.4.0 h1:RzRqFcjH4nE5C6oTAxhBtoE2IRyjBSa62SCbyPidvls=
@@ -36,6 +34,8 @@ github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfn
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/mediocregopher/mediocre-go-lib/v2 v2.0.0-beta.1.0.20221113151154-07f3889a705b h1:A+IqPY72GXChyCje7YqnZrb8Q4ajUqft/etsmIOobu4=
+github.com/mediocregopher/mediocre-go-lib/v2 v2.0.0-beta.1.0.20221113151154-07f3889a705b/go.mod h1:wOZVlnKYvIbkzyCJ3dxy1k40XkirvCd1pisX2O91qoQ=
 github.com/minio/md5-simd v1.1.0 h1:QPfiOqlZH+Cj9teu0t9b1nTBfPbyTl16Of5MeuShdK4=
 github.com/minio/md5-simd v1.1.0/go.mod h1:XpBqgZULrMYD3R+M28PcmP0CkI7PEMzB3U77ZrKZ0Gw=
 github.com/minio/minio-go/v7 v7.0.28 h1:VMr3K5qGIEt+/KW3poopRh8mzi5RwuCjmrmstK196Fg=
@@ -49,8 +49,6 @@ github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd h1:TRLaZ9cD/w
 github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q=
 github.com/modern-go/reflect2 v1.0.2 h1:xBagoLtFs94CBntxluKeaWgTMpvLxC4ur3nMaC9Gz0M=
 github.com/modern-go/reflect2 v1.0.2/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk=
-github.com/nlepage/go-tarfs v1.1.0 h1:bsACOiZMB/zFjYG/sE01070i9Fl26MnRpw0L6WuyfVs=
-github.com/nlepage/go-tarfs v1.1.0/go.mod h1:IhxRcLhLkawBetnwu/JNuoPkq/6cclAllhgEa6SmzS8=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/rs/xid v1.2.1 h1:mhH9Nq+C1fY2l1XIpgxIiUOfNpRBYH1kKcr+qfKgjRc=
@@ -71,7 +69,6 @@ github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXf
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.1 h1:5TQK59W5E3v0r2duFAb7P95B6hEeOyEnHRa8MjYSMTY=
-github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/tklauser/go-sysconf v0.3.10 h1:IJ1AZGZRWbY8T5Vfk04D9WOA5WSejdflXxP03OUqALw=
 github.com/tklauser/go-sysconf v0.3.10/go.mod h1:C8XykCvCb+Gn0oNCWPIlcb0RuglQTYaQ2hGm7jmxEFk=
 github.com/tklauser/numcpus v0.4.0 h1:E53Dm1HjH1/R2/aoCtXtPgzmElmn51aOkhCFSuZq//o=