[feat] Add verbosity levels to the debug package (#2851)

* [feat] Add verbosity levels to the debug package

Use debug.V(N).Log instead of debug.Log to indicate message
verbosity (higher numbers indicate more verbose messages).

Use GOPASS_DEBUG_VERBOSE=N to control the desired level
of verbosity in the log output.

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

* Document the verbosity env vars.

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

* Allow negative verbosity values

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

---------

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

docs/config.md

@@ -20,6 +20,7 @@ Some configuration options are only available through setting environment variab
 | `GOPASS_DEBUG_LOG_SECRETS`   | `bool`   | Set to any non-empty value to enable logging of credentials                                                                                                       |
 | `GOPASS_DEBUG_LOG`           | `string` | Set to a filename to enable debug logging (only set GOPASS_DEBUG to log to stderr)                                                                                |
 | `GOPASS_DEBUG`               | `bool`   | Set to any non-empty value to enable verbose debug output, by default on stderr, unless GOPASS_DEBUG_LOG is set                                                   |
+| `GOPASS_DEBUG_VERBOSE`       | `int`    | Set to any integer value larger than zero to increase the verbosity of debug output                                                                                |
 | `GOPASS_EXTERNAL_PWGEN`      | `string` | Use an external password generator. See [Features](features.md#using-custom-password-generators) for details                                                      |
 | `GOPASS_FORCE_CHECK`         | `string` | (internal) Force the updater to check for updates. Used for testing.                                                                                              |
 | `GOPASS_FORCE_UPDATE`        | `bool`   | Set to any non-empty value to force an update (if available)                                                                                                      |

internal/tree/node.go

@@ -2,6 +2,8 @@ package tree
 
 import (
 	"bytes"
+
+	"github.com/gopasspw/gopass/pkg/debug"
 )
 
 // Node is a tree node.
@@ -109,7 +111,7 @@ func (n Node) Merge(other Node) *Node {
 		r.Subtree = other.Subtree
 	}
 
-	// debug.Log("merged %+v and %+v into %+v", n, other, r)
+	debug.V(4).Log("merged %+v and %+v into %+v", n, other, r)
 
 	return &r
 }

internal/tree/root.go

@@ -6,6 +6,7 @@ import (
 	"strings"
 
 	"github.com/fatih/color"
+	"github.com/gopasspw/gopass/pkg/debug"
 )
 
 const (
@@ -60,7 +61,7 @@ func (r *Root) AddTemplate(path string) error {
 func (r *Root) insert(path string, template bool, mountPath string) error {
 	t := r.Subtree
 
-	// debug.Log("adding: %s [tpl: %t, mp: %q]", path, template, mountPath)
+	debug.V(4).Log("adding: %s [tpl: %t, mp: %q]", path, template, mountPath)
 
 	// split the path into its components, iterate over them and create
 	// the tree structure. Everything but the last element is a folder.
@@ -82,10 +83,10 @@ func (r *Root) insert(path string, template bool, mountPath string) error {
 			}
 		}
 
-		// debug.Log("[%d] %s -> Node: %+v", i, e, n)
+		debug.V(4).Log("[%d] %s -> Node: %+v", i, e, n)
 
 		node := t.Insert(n)
-		// debug.Log("node after insert: %+v", node)
+		debug.V(4).Log("node after insert: %+v", node)
 
 		// do we need to extend an existing subtree?
 		if i < len(p)-1 && node.Subtree == nil {

pkg/debug/debug.go

@@ -8,6 +8,7 @@ import (
 	"path"
 	"path/filepath"
 	"runtime"
+	"strconv"
 	"strings"
 )
 
@@ -17,15 +18,24 @@ var (
 	// Stderr is exported for tests.
 	Stderr io.Writer = os.Stderr
 	// LogWriter is exposed for consuming extra command output, if needed.
-	LogWriter  io.Writer = io.Discard
-	logSecrets bool
+	LogWriter io.Writer = io.Discard
 )
 
 var opts struct {
-	logger  *log.Logger
-	funcs   map[string]bool
-	files   map[string]bool
-	logFile *os.File
+	logger     *log.Logger
+	funcs      map[string]bool
+	files      map[string]bool
+	logFile    *os.File
+	logSecrets bool
+	verbosity  int
+}
+
+// v is a verbosity level.
+type v int
+
+// V returns a logger at the given verbosity level.
+func V(n int) v {
+	return v(n)
 }
 
 var logFn = doNotLog
@@ -38,6 +48,12 @@ func initDebug() bool {
 		_ = opts.logFile.Close()
 	}
 
+	if l := os.Getenv("GOPASS_DEBUG_VERBOSE"); l != "" {
+		if iv, err := strconv.Atoi(l); err == nil {
+			opts.verbosity = iv
+		}
+	}
+
 	if os.Getenv("GOPASS_DEBUG") == "" && os.Getenv("GOPASS_DEBUG_LOG") == "" {
 		logFn = doNotLog
 
@@ -47,9 +63,9 @@ func initDebug() bool {
 	// we need to explicitly set logSecrets to false in case tests run under an environment
 	// where GOPASS_DEBUG_LOG_SECRETS is true. Otherwise setting it to false in the test
 	// context won't have any effect.
-	logSecrets = false
+	opts.logSecrets = false
 	if sv := os.Getenv("GOPASS_DEBUG_LOG_SECRETS"); sv != "" && sv != "false" {
-		logSecrets = true
+		opts.logSecrets = true
 	}
 
 	initDebugLogger()
@@ -191,22 +207,34 @@ func checkFilter(filter map[string]bool, key string) bool {
 	return false
 }
 
+// Log logs a statement to Stderr (unless filtered) and the
+// debug log file (if enabled), but only if the verbosity
+// level is greater or equal to the given level.
+func (n v) Log(f string, args ...any) {
+	logFn(int(n), 0, f, args...)
+}
+
 // Log logs a statement to Stderr (unless filtered) and the
 // debug log file (if enabled).
 func Log(f string, args ...any) {
-	logFn(0, f, args...)
+	logFn(0, 0, f, args...)
 }
 
 // LogN logs a statement to Stderr (unless filtered) and the
 // debug log file (if enabled). The offset will be applied to
 // the runtime position.
 func LogN(offset int, f string, args ...any) {
-	logFn(offset, f, args...)
+	logFn(0, offset, f, args...)
 }
 
-func doNotLog(offset int, f string, args ...any) {}
+func doNotLog(verbosity, offset int, f string, args ...any) {}
+
+func doLog(verbosity, offset int, f string, args ...any) {
+	// if the log message is too verbose for the requested verbosity level, skip it
+	if verbosity > opts.verbosity {
+		return
+	}
 
-func doLog(offset int, f string, args ...any) {
 	fn, dir, file, line := getPosition(offset)
 
 	if len(f) == 0 || f[len(f)-1] != '\n' {
@@ -224,7 +252,7 @@ func doLog(offset int, f string, args ...any) {
 	argsi := make([]any, len(args))
 	for i, item := range args {
 		argsi[i] = item
-		if secreter, ok := item.(Safer); ok && !logSecrets {
+		if secreter, ok := item.(Safer); ok && !opts.logSecrets {
 			argsi[i] = secreter.SafeStr()
 
 			continue

pkg/debug/debug_test.go

@@ -84,7 +84,7 @@ func TestDebugSecret(t *testing.T) {
 	// it's been already initialized, need to re-init
 	assert.True(t, initDebug())
 
-	assert.True(t, logSecrets)
+	assert.True(t, opts.logSecrets)
 
 	Log("foo")
 	Log("%s", testSecret("secret"))

pkg/gitconfig/config.go

@@ -122,16 +122,16 @@ func (c *Config) Set(key, value string) error {
 	vs[0] = value
 	c.vars[key] = vs
 
-	// debug.Log("set %q to %q", key, value)
+	debug.V(3).Log("set %q to %q", key, value)
 
 	// a new key, insert it into an existing section, if any
 	if !present {
-		// debug.Log("inserting value")
+		debug.V(3).Log("inserting value")
 
 		return c.insertValue(key, value)
 	}
 
-	// debug.Log("updating value")
+	debug.V(3).Log("updating value")
 
 	var updated bool
 
@@ -146,7 +146,7 @@ func (c *Config) Set(key, value string) error {
 }
 
 func (c *Config) insertValue(key, value string) error {
-	// debug.Log("input (%s: %s): \n--------------\n%s\n--------------\n", key, value, strings.Join(strings.Split("- "+c.raw.String(), "\n"), "\n- "))
+	debug.V(3).Log("input (%s: %s): \n--------------\n%s\n--------------\n", key, value, strings.Join(strings.Split("- "+c.raw.String(), "\n"), "\n- "))
 
 	wSection, wSubsection, wKey := splitKey(key)
 
@@ -204,7 +204,7 @@ func (c *Config) insertValue(key, value string) error {
 	c.raw.WriteString(strings.Join(lines, "\n"))
 	c.raw.WriteString("\n")
 
-	// debug.Log("output: \n--------------\n%s\n--------------\n", strings.Join(strings.Split("+ "+c.raw.String(), "\n"), "\n+ "))
+	debug.V(3).Log("output: \n--------------\n%s\n--------------\n", strings.Join(strings.Split("+ "+c.raw.String(), "\n"), "\n+ "))
 
 	return c.flushRaw()
 }
@@ -231,15 +231,15 @@ func parseSectionHeader(line string) (section, subsection string, skip bool) { /
 // rewriteRaw is used to rewrite the raw config copy. It is used for set and unset operations
 // with different callbacks each.
 func (c *Config) rewriteRaw(key, value string, cb parseFunc) error {
-	// debug.Log("input (%s: %s): \n--------------\n%s\n--------------\n", key, value, strings.Join(strings.Split("- "+c.raw.String(), "\n"), "\n- "))
+	debug.V(3).Log("input (%s: %s): \n--------------\n%s\n--------------\n", key, value, strings.Join(strings.Split("- "+c.raw.String(), "\n"), "\n- "))
 
 	lines := parseConfig(strings.NewReader(c.raw.String()), key, value, cb)
 
 	c.raw = strings.Builder{}
 	c.raw.WriteString(strings.Join(lines, "\n"))
 	c.raw.WriteString("\n")
 
-	// debug.Log("output: \n--------------\n%s\n--------------\n", strings.Join(strings.Split("+ "+c.raw.String(), "\n"), "\n+ "))
+	debug.V(3).Log("output: \n--------------\n%s\n--------------\n", strings.Join(strings.Split("+ "+c.raw.String(), "\n"), "\n+ "))
 
 	return c.flushRaw()
 }
@@ -255,7 +255,7 @@ func (c *Config) flushRaw() error {
 		return err
 	}
 
-	// debug.Log("writing config to %s: \n--------------\n%s\n--------------", c.path, c.raw.String())
+	debug.V(3).Log("writing config to %s: \n--------------\n%s\n--------------", c.path, c.raw.String())
 
 	if err := os.WriteFile(c.path, []byte(c.raw.String()), 0o600); err != nil {
 		return fmt.Errorf("failed to write config to %s: %w", c.path, err)
@@ -314,7 +314,7 @@ func parseConfig(in io.Reader, key, value string, cb parseFunc) []string {
 		// These are odd but we should still support them.
 		k, v, found := strings.Cut(line, " = ")
 		if !found {
-			// debug.Log("no valid KV-pair on line: %q", line)
+			debug.V(3).Log("no valid KV-pair on line: %q", line)
 
 			continue
 		}
@@ -401,7 +401,7 @@ func ParseConfig(r io.Reader) *Config {
 	c.raw.WriteString(strings.Join(lines, "\n"))
 	c.raw.WriteString("\n")
 
-	// debug.Log("processed config: %s\nvars: %+v", c.raw.String(), c.vars)
+	debug.V(3).Log("processed config: %s\nvars: %+v", c.raw.String(), c.vars)
 
 	return c
 }

pkg/gitconfig/configs.go

@@ -113,7 +113,7 @@ func (cs *Configs) LoadAll(workdir string) *Configs {
 		worktreeConfigPath := filepath.Join(workdir, cs.WorktreeConfig)
 		c, err := LoadConfig(worktreeConfigPath)
 		if err != nil {
-			// debug.Log("[%s] failed to load worktree config from %s: %s", cs.Name, worktreeConfigPath, err)
+			debug.V(3).Log("[%s] failed to load worktree config from %s: %s", cs.Name, worktreeConfigPath, err)
 			// set the path just in case we want to modify / write to it later
 			cs.worktree.path = worktreeConfigPath
 		} else {
@@ -216,7 +216,7 @@ func (cs *Configs) Get(key string) string {
 		}
 	}
 
-	// debug.Log("[%s] no value for %s found", cs.Name, key)
+	debug.V(3).Log("[%s] no value for %s found", cs.Name, key)
 
 	return ""
 }
@@ -240,7 +240,7 @@ func (cs *Configs) GetAll(key string) []string {
 		}
 	}
 
-	// debug.Log("[%s] no value for %s found", cs.Name, key)
+	debug.V(3).Log("[%s] no value for %s found", cs.Name, key)
 
 	return nil
 }
@@ -255,7 +255,7 @@ func (cs *Configs) GetGlobal(key string) string {
 		return v
 	}
 
-	// debug.Log("[%s] no value for %s found", cs.Name, key)
+	debug.V(3).Log("[%s] no value for %s found", cs.Name, key)
 
 	return ""
 }
@@ -270,7 +270,7 @@ func (cs *Configs) GetLocal(key string) string {
 		return v
 	}
 
-	// debug.Log("[%s] no value for %s found", cs.Name, key)
+	debug.V(3).Log("[%s] no value for %s found", cs.Name, key)
 
 	return ""
 }