gopass/pkg/debug/debug.go

package debug

import (
	"fmt"
	"io"
	"log"
	"os"
	"path"
	"path/filepath"
	"runtime"
	"strconv"
	"strings"
)

var (
	// Stdout is exported for tests.
	Stdout io.Writer = os.Stdout
	// 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
)

var opts struct {
	logger     *log.Logger
	funcs      map[string]bool
	files      map[string]bool
	logFile    *os.File
	logSecrets bool
	verbosity  int
	pid        int
}

// v is a verbosity level.
type v int

// V returns a logger at the given verbosity level.
// The higher the number, the more verbose the logging.
func V(n int) v {
	return v(n)
}

var logFn = doNotLog

// make sure all initializations happens before the init func.
var enabled = initDebug()

func initDebug() bool {
	if opts.logFile != nil {
		_ = 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

		return false
	}

	// 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.
	opts.logSecrets = false
	if sv := os.Getenv("GOPASS_DEBUG_LOG_SECRETS"); sv != "" && sv != "false" {
		opts.logSecrets = true
	}

	opts.pid = os.Getpid()

	initDebugLogger()
	initDebugTags()

	logFn = doLog

	return true
}

func initDebugLogger() {
	debugfile := os.Getenv("GOPASS_DEBUG_LOG")
	if debugfile == "" {
		opts.logger = log.New(os.Stderr, "", log.Ldate|log.Lmicroseconds)
		LogWriter = os.Stderr

		return
	}

	f, err := os.OpenFile(debugfile, os.O_WRONLY|os.O_APPEND, 0o600)
	if err == nil {
		// seek to the end of the file (offset, whence [2 = end])
		_, err := f.Seek(0, 2)
		if err != nil {
			_ = f.Close()
			fmt.Fprintf(Stderr, "unable to seek to end of %v: %v\n", debugfile, err)
			os.Exit(3)
		}
	}

	if err != nil && os.IsNotExist(err) {
		f, err = os.OpenFile(debugfile, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0o600)
	}

	if err != nil {
		fmt.Fprintf(Stderr, "unable to open debug log file %v: %v\n", debugfile, err)
		os.Exit(2)
	}

	opts.logFile = f
	opts.logger = log.New(f, "", log.Ldate|log.Lmicroseconds)
	LogWriter = f
}

func parseFilter(envname string, pad func(string) string) map[string]bool {
	filter := make(map[string]bool)

	env := os.Getenv(envname)
	if env == "" {
		return filter
	}

	for fn := range strings.SplitSeq(env, ",") {
		t := pad(strings.TrimSpace(fn))
		val := true

		switch t[0] {
		case '-':
			val = false
			t = t[1:]
		case '+':
			val = true
			t = t[1:]
		}

		// test pattern
		_, err := path.Match(t, "")
		if err != nil {
			fmt.Fprintf(Stderr, "error: invalid pattern %q: %v\n", t, err)
			os.Exit(5)
		}

		filter[t] = val
	}

	return filter
}

func padFunc(s string) string {
	if s == "all" {
		return s
	}

	return s
}

func padFile(s string) string {
	if s == "all" {
		return s
	}

	if !strings.Contains(s, "/") {
		s = "*/" + s
	}

	if !strings.Contains(s, ":") {
		s += ":*"
	}

	return s
}

func initDebugTags() {
	opts.funcs = parseFilter("GOPASS_DEBUG_FUNCS", padFunc)
	opts.files = parseFilter("GOPASS_DEBUG_FILES", padFile)
}

func getPosition(offset int) (fn, dir, file string, line int) { //nolint:nonamedreturns
	pc, file, line, ok := runtime.Caller(3 + offset)
	if !ok {
		return "", "", "", 0
	}

	dirname := filepath.Base(filepath.Dir(file))
	filename := filepath.Base(file)

	f := runtime.FuncForPC(pc)

	return path.Base(f.Name()), dirname, filename, line
}

func checkFilter(filter map[string]bool, key string) bool {
	// check if exact match
	if v, ok := filter[key]; ok {
		return v
	}

	// check globbing
	for k, v := range filter {
		if m, _ := path.Match(k, key); m {
			return v
		}
	}

	// check if tag "all" is enabled
	if v, ok := filter["all"]; ok && v {
		return true
	}

	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.
//
// This is a no-op if the verbosity level is not high enough.
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).
//
// This is a no-op if debugging is not enabled.
func Log(f string, args ...any) {
	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.
//
// This is a no-op if debugging is not enabled.
func LogN(offset int, f string, args ...any) {
	logFn(0, offset, f, args...)
}

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
	}

	fn, dir, file, line := getPosition(offset)

	if len(f) == 0 || f[len(f)-1] != '\n' {
		f += "\n"
	}

	type Shortener interface {
		Str() string
	}

	type Safer interface {
		SafeStr() string
	}

	argsi := make([]any, len(args))
	for i, item := range args {
		argsi[i] = item
		if secreter, ok := item.(Safer); ok && !opts.logSecrets {
			argsi[i] = secreter.SafeStr()

			continue
		}

		if shortener, ok := item.(Shortener); ok {
			argsi[i] = shortener.Str()
		}
	}

	pos := fmt.Sprintf("%s/%s:%d", dir, file, line)

	formatString := fmt.Sprintf("%d\t%-20s\t%-20s\t%s", opts.pid, pos, fn, f)

	dbgprint := func() {
		fmt.Fprintf(Stderr, formatString, argsi...)
	}

	if opts.logger != nil {
		opts.logger.Printf(formatString, argsi...)
	}

	filename := fmt.Sprintf("%s/%s:%d", dir, file, line)
	if checkFilter(opts.files, filename) {
		dbgprint()

		return
	}

	if checkFilter(opts.funcs, fn) {
		dbgprint()
	}
}

// IsEnabled returns true if debug logging was enabled.
// This is useful to avoid expensive computations if debugging is not enabled.
func IsEnabled() bool {
	return enabled
}