From 2ae06a7a01abb117eabdec51a2aefc38080592cc Mon Sep 17 00:00:00 2001
From: Alexander Neumann <alexander@bumpern.de>
Date: Tue, 27 Sep 2016 22:23:34 +0200
Subject: [PATCH] Rework debug log function

---
 src/restic/debug/debug.go         | 138 +++++++++++++++++++-----------
 src/restic/debug/debug_release.go |   1 +
 2 files changed, 91 insertions(+), 48 deletions(-)

diff --git a/src/restic/debug/debug.go b/src/restic/debug/debug.go
index b1ab2b38c..e7d05123e 100644
--- a/src/restic/debug/debug.go
+++ b/src/restic/debug/debug.go
@@ -19,13 +19,14 @@ import (
 )
 
 type process struct {
-	tag       string
+	fn        string
 	goroutine int
 }
 
 var opts struct {
 	logger *log.Logger
-	tags   map[string]bool
+	funcs  map[string]bool
+	files  map[string]bool
 	last   map[process]time.Time
 	m      sync.Mutex
 }
@@ -73,23 +74,16 @@ func initDebugLogger() {
 	opts.logger = log.New(f, "", log.LstdFlags)
 }
 
-func initDebugTags() {
-	opts.tags = make(map[string]bool)
-	opts.last = make(map[process]time.Time)
+func parseFilter(envname string, pad func(string) string) map[string]bool {
+	filter := make(map[string]bool)
 
-	// defaults
-	opts.tags["break"] = true
-
-	// initialize tags
-	env := os.Getenv("DEBUG_TAGS")
-	if len(env) == 0 {
-		return
+	env := os.Getenv(envname)
+	if env == "" {
+		return filter
 	}
 
-	tags := []string{}
-
-	for _, tag := range strings.Split(env, ",") {
-		t := strings.TrimSpace(tag)
+	for _, fn := range strings.Split(env, ",") {
+		t := pad(strings.TrimSpace(fn))
 		val := true
 		if t[0] == '-' {
 			val = false
@@ -106,11 +100,45 @@ func initDebugTags() {
 			os.Exit(5)
 		}
 
-		opts.tags[t] = val
-		tags = append(tags, tag)
+		filter[t] = val
 	}
 
-	fmt.Fprintf(os.Stderr, "debug log enabled for: %v\n", tags)
+	return filter
+}
+
+func padFunc(s string) string {
+	if s == "all" {
+		return s
+	}
+
+	if !strings.Contains(s, "/") {
+		s = "*/" + s
+	}
+
+	return s
+}
+
+func padFile(s string) string {
+	if s == "all" {
+		return s
+	}
+
+	if !strings.Contains(s, "/") {
+		s = "*/" + s
+	}
+
+	if !strings.Contains(s, ":") {
+		s = s + ":*"
+	}
+
+	return s
+}
+
+func initDebugTags() {
+	opts.last = make(map[process]time.Time)
+
+	opts.funcs = parseFilter("DEBUG_FUNCS", padFunc)
+	opts.files = parseFilter("DEBUG_FILES", padFile)
 }
 
 // taken from https://github.com/VividCortex/trace
@@ -124,40 +152,68 @@ func goroutineNum() int {
 }
 
 // taken from https://github.com/VividCortex/trace
-func getPosition(goroutine int) string {
-	_, file, line, ok := runtime.Caller(2)
+func getPosition() (fn, dir, file string, line int) {
+	pc, file, line, ok := runtime.Caller(2)
 	if !ok {
-		return ""
+		return "", "", "", 0
 	}
 
-	return fmt.Sprintf("%3d %s:%d", goroutine, filepath.Base(file), line)
+	dirname, filename := filepath.Base(filepath.Dir(file)), filepath.Base(file)
+
+	Func := runtime.FuncForPC(pc)
+
+	return Func.Name(), dirname, filename, line
 }
 
-var maxTagLen = 10
+func checkFilter(filter map[string]bool, key string) bool {
+	// check if key is enabled directly
+	if v, ok := filter[key]; ok {
+		return v
+	}
 
-func Log(tag string, f string, args ...interface{}) {
+	// check for 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
+}
+
+var maxPosLen = 10
+
+// Log prints a message to the debug log (if debug is enabled).
+func Log(x string, f string, args ...interface{}) {
 	opts.m.Lock()
 	defer opts.m.Unlock()
 
+	fn, dir, file, line := getPosition()
 	goroutine := goroutineNum()
 
-	last, ok := opts.last[process{tag, goroutine}]
+	last, ok := opts.last[process{fn, goroutine}]
 	if !ok {
 		last = time.Now()
 	}
 	current := time.Now()
-	opts.last[process{tag, goroutine}] = current
+	opts.last[process{fn, goroutine}] = current
 
 	if len(f) == 0 || f[len(f)-1] != '\n' {
 		f += "\n"
 	}
 
-	if len(tag) > maxTagLen {
-		maxTagLen = len(tag)
+	pos := fmt.Sprintf("%s/%s:%d", dir, file, line)
+	if len(pos) > maxPosLen {
+		maxPosLen = len(pos)
 	}
 
-	formatStringTag := "%2.3f [%" + strconv.FormatInt(int64(maxTagLen), 10) + "s]"
-	formatString := fmt.Sprintf(formatStringTag+" %s %s", current.Sub(last).Seconds(), tag, getPosition(goroutine), f)
+	formatStringTag := "%2.3f [%" + strconv.FormatInt(int64(maxPosLen), 10) + "s]"
+	formatString := fmt.Sprintf(formatStringTag+" %s", current.Sub(last).Seconds(), pos, f)
 
 	dbgprint := func() {
 		fmt.Fprintf(os.Stderr, formatString, args...)
@@ -167,26 +223,12 @@ func Log(tag string, f string, args ...interface{}) {
 		opts.logger.Printf(formatString, args...)
 	}
 
-	// check if tag is enabled directly
-	if v, ok := opts.tags[tag]; ok {
-		if v {
-			dbgprint()
-		}
+	if checkFilter(opts.files, fmt.Sprintf("%s/%s:%d", dir, file, line)) {
+		dbgprint()
 		return
 	}
 
-	// check for globbing
-	for k, v := range opts.tags {
-		if m, _ := path.Match(k, tag); m {
-			if v {
-				dbgprint()
-			}
-			return
-		}
-	}
-
-	// check if tag "all" is enabled
-	if v, ok := opts.tags["all"]; ok && v {
+	if checkFilter(opts.funcs, fn) {
 		dbgprint()
 	}
 }
diff --git a/src/restic/debug/debug_release.go b/src/restic/debug/debug_release.go
index 9062d8ce8..c0ba510d1 100644
--- a/src/restic/debug/debug_release.go
+++ b/src/restic/debug/debug_release.go
@@ -2,4 +2,5 @@
 
 package debug
 
+// Log prints a message to the debug log (if debug is enabled).
 func Log(tag string, fmt string, args ...interface{}) {}