Improve logging and pretty printing (#3286)

* [chore] Add PID to the debug logs

This helps differentiate between gopass foreground and background (e.g.
agent) processes.

Signed-off-by: Dominik Schulz <dominik.schulz@gauner.org>

* [chore] Adjust logging severities and improve pretty printing

Signed-off-by: Dominik Schulz <dominik.schulz@gauner.org>

---------

Signed-off-by: Dominik Schulz <dominik.schulz@gauner.org>

internal/backend/crypto/age/age.go

@@ -175,3 +175,23 @@ func (a *Age) identitiesToString(ids []age.Identity) (string, error) {
 
 	return sb.String(), nil
 }
+
+// String implements fmt.Stringer.
+func (a *Age) String() string {
+	var sb strings.Builder
+	sb.WriteString("Age(")
+	if a == nil {
+		sb.WriteString("<nil>)")
+
+		return sb.String()
+	}
+	sb.WriteString("Identity: ")
+	sb.WriteString(a.identity)
+	if a.sshKeyPath != "" {
+		sb.WriteString(", SSHKeyPath: ")
+		sb.WriteString(a.sshKeyPath)
+	}
+	sb.WriteString(")")
+
+	return sb.String()
+}

internal/backend/crypto/gpg/cli/gpg.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"fmt"
 	"os"
+	"strings"
 	"time"
 
 	"github.com/gopasspw/gopass/internal/backend/crypto/gpg"
@@ -120,3 +121,21 @@ func (g *GPG) Binary() string {
 
 	return g.binary
 }
+
+// String implements fmt.Stringer.
+func (g *GPG) String() string {
+	var sb strings.Builder
+	sb.WriteString("gpgcli(")
+	if g == nil {
+		sb.WriteString("<nil>)")
+
+		return sb.String()
+	}
+	sb.WriteString("binary:")
+	sb.WriteString(g.binary)
+	sb.WriteString(",args: [")
+	sb.WriteString(strings.Join(g.args, " "))
+	sb.WriteString("])")
+
+	return sb.String()
+}

internal/backend/crypto/plain/backend.go

@@ -171,3 +171,8 @@ func (m *Mocker) GetFingerprint(ctx context.Context, key []byte) (string, error)
 func (m *Mocker) Concurrency() int {
 	return runtime.NumCPU()
 }
+
+// String implements fmt.Stringer.
+func (m *Mocker) String() string {
+	return "Plaintext(Encrypt/Decrypt no-op)"
+}

internal/backend/storage.go

@@ -60,14 +60,14 @@ func DetectStorage(ctx context.Context, path string) (Storage, error) {
 	// The call to HasStorageBackend is important since GetStorageBackend will always return FS
 	// if nothing is found in the context.
 	if be, err := StorageRegistry.Get(GetStorageBackend(ctx)); HasStorageBackend(ctx) && err == nil {
-		debug.V(1).Log("Trying requested %s for %s", be, path)
+		debug.V(1).Log("Trying requested storage backend %q for %q", be, path)
 		st, err := be.New(ctx, path)
 		if err == nil {
-			debug.Log("Using requested %s for %s", be, path)
+			debug.Log("Successfully loaded requested storage backend %q for %q", be, path)
 
 			return st, nil
 		}
-		debug.Log("Failed to use requested %s for %s: %s", be, path, err)
+		debug.Log("Failed to use requested storage backend %q for %s: %q", be, path, err)
 
 		// fallback to FS
 		be, err := StorageRegistry.Get(FS)
@@ -81,13 +81,13 @@ func DetectStorage(ctx context.Context, path string) (Storage, error) {
 
 	// Nothing requested in the context. Try to detect the backend.
 	for _, be := range StorageRegistry.Prioritized() {
-		debug.V(1).Log("Trying %s for %s", be, path)
+		debug.V(1).Log("Trying storage backend %q for %q", be, path)
 		if err := be.Handles(ctx, path); err != nil {
 			debug.Log("failed to use %s for %s: %s", be, path, err)
 
 			continue
 		}
-		debug.Log("Using detected %s for %s", be, path)
+		debug.Log("Detected storage backend %q for %q", be, path)
 
 		return be.New(ctx, path)
 	}
@@ -105,7 +105,7 @@ func DetectStorage(ctx context.Context, path string) (Storage, error) {
 // NewStorage initializes an existing storage backend.
 func NewStorage(ctx context.Context, id StorageBackend, path string) (Storage, error) {
 	if be, err := StorageRegistry.Get(id); err == nil {
-		debug.Log("Using %s for %s", be, path)
+		debug.Log("Using storage backend %q for %q", be, path)
 
 		return be.New(ctx, path)
 	}

internal/reminder/reminder.go

@@ -36,20 +36,20 @@ func (s *Store) LastSeen(key string) time.Time {
 
 	res, err := s.cache.Get(key)
 	if err != nil {
-		debug.Log("failed to read %q from cache: %s", key, err)
+		debug.V(2).Log("failed to read %q from cache: %s", key, err)
 
 		return t
 	}
 
 	if len(res) < 1 {
-		debug.Log("cache result is empty")
+		debug.V(1).Log("cache result is empty")
 
 		return t
 	}
 
 	ts, err := time.Parse(time.RFC3339, res[0])
 	if err != nil {
-		debug.Log("failed to parse stored time %q: %s", err)
+		debug.V(1).Log("failed to parse stored time %q: %s", err)
 
 		return t
 	}

internal/store/leaf/store.go

@@ -65,14 +65,14 @@ func New(ctx context.Context, alias, path string) (*Store, error) {
 		return nil, fmt.Errorf("failed to init storage backend: %w", err)
 	}
 
-	debug.Log("Storage for %s => %s initialized as %v", alias, path, s.storage)
+	debug.Log("Storage for %q (%q) initialized as %s", alias, path, s.storage)
 
 	// init crypto backend
 	if err := s.initCryptoBackend(ctx); err != nil {
 		return nil, fmt.Errorf("failed to init crypto backend: %w", err)
 	}
 
-	debug.Log("Crypto for %s => %s initialized as %v", alias, path, s.crypto)
+	debug.Log("Crypto for %q (%q) initialized as %s", alias, path, s.crypto)
 
 	return s, nil
 }

internal/store/root/list.go

@@ -62,9 +62,9 @@ func (r *Store) Tree(ctx context.Context) (*tree.Root, error) {
 		return nil, err
 	}
 
-	debug.Log("[root] adding files: %q", sf)
+	debug.V(1).Log("[root] adding files: %q", sf)
 	addFileFunc(sf...)
-	debug.Log("[root] Tree: %s", root.Format(-1))
+	debug.V(1).Log("[root] Tree: %s", root.Format(-1))
 	addTplFunc(r.store.ListTemplates(ctx, "")...)
 
 	mps := r.MountPoints()
@@ -85,7 +85,7 @@ func (r *Store) Tree(ctx context.Context) (*tree.Root, error) {
 			return nil, fmt.Errorf("failed to add file: %w", err)
 		}
 
-		debug.Log("[%s] adding files: %q", alias, sf)
+		debug.V(1).Log("[%s] adding files: %q", alias, sf)
 		addFileFunc(sf...)
 		addTplFunc(substore.ListTemplates(ctx, alias)...)
 	}

main.go

@@ -82,12 +82,13 @@ func main() {
 	sv := getVersion()
 	cli.VersionPrinter = makeVersionPrinter(os.Stdout, sv)
 
+	debug.Log("gopass %s starting. Args: %v", sv.String(), os.Args)
+
 	// run the app
 	q := queue.New(ctx)
 	ctx = queue.WithQueue(ctx, q)
 	ctx, app := setupApp(ctx, sv)
 
-	debug.Log("gopass %s starting ...", sv.String())
 	if err := app.RunContext(ctx, os.Args); err != nil {
 		log.Fatal(err)
 	}

pkg/debug/debug.go

@@ -28,6 +28,7 @@ var opts struct {
 	logFile    *os.File
 	logSecrets bool
 	verbosity  int
+	pid        int
 }
 
 // v is a verbosity level.
@@ -69,6 +70,8 @@ func initDebug() bool {
 		opts.logSecrets = true
 	}
 
+	opts.pid = os.Getpid()
+
 	initDebugLogger()
 	initDebugTags()
 
@@ -119,7 +122,7 @@ func parseFilter(envname string, pad func(string) string) map[string]bool {
 		return filter
 	}
 
-	for _, fn := range strings.Split(env, ",") {
+	for fn := range strings.SplitSeq(env, ",") {
 		t := pad(strings.TrimSpace(fn))
 		val := true
 
@@ -273,7 +276,7 @@ func doLog(verbosity, offset int, f string, args ...any) {
 
 	pos := fmt.Sprintf("%s/%s:%d", dir, file, line)
 
-	formatString := fmt.Sprintf("%s\t%s\t%s", pos, fn, f)
+	formatString := fmt.Sprintf("%d\t%-20s\t%-20s\t%s", opts.pid, pos, fn, f)
 
 	dbgprint := func() {
 		fmt.Fprintf(Stderr, formatString, argsi...)