Introduce debug tags and debug breaks

The environment variable DEBUG_TAGS can be used to control what is
printed on stderr. Example:

    DEBUG_TAGS="+all,-Archiver.*" ./restic backup foo

The variable DEBUG_BREAK can be used to set a breakpoint (implemented
using SIGSTOP):

    DEBUG_BREAK=Archiver.Snapshot ./restic backup foo

archiver.go

@@ -64,12 +64,12 @@ func (arch *Archiver) Save(t backend.Type, data []byte) (Blob, error) {
 	// compute plaintext hash
 	id := backend.Hash(data)
 
-	debug("Save(%v, %v)\n", t, id.Str())
+	debug("Archiver.Save", "Save(%v, %v)\n", t, id.Str())
 
 	// test if this blob is already known
 	blob, err := arch.m.FindID(id)
 	if err == nil {
-		debug("Save(%v, %v): reusing %v\n", t, id.Str(), blob.Storage.Str())
+		debug("Archiver.Save", "Save(%v, %v): reusing %v\n", t, id.Str(), blob.Storage.Str())
 		id.Free()
 		return blob, nil
 	}
@@ -84,7 +84,7 @@ func (arch *Archiver) Save(t backend.Type, data []byte) (Blob, error) {
 	// one and remove the other. This happens if the same plaintext blob was
 	// stored concurrently and finished earlier than this blob.
 	if blob.Storage.Compare(smapblob.Storage) != 0 {
-		debug("using other block, removing %v\n", blob.Storage.Str())
+		debug("Archiver.Save", "using other block, removing %v\n", blob.Storage.Str())
 
 		// remove the blob again
 		// TODO: implement a list of blobs in transport, so this doesn't happen so often
@@ -94,7 +94,7 @@ func (arch *Archiver) Save(t backend.Type, data []byte) (Blob, error) {
 		}
 	}
 
-	debug(": Save(%v, %v): new blob %v\n", t, id.Str(), blob)
+	debug("Archiver.Save", "Save(%v, %v): new blob %v\n", t, id.Str(), blob)
 
 	return smapblob, nil
 }
@@ -262,7 +262,7 @@ func (arch *Archiver) SaveFile(node *Node) (Blobs, error) {
 }
 
 func (arch *Archiver) saveTree(t *Tree) (Blob, error) {
-	debug("saveTree(%v)\n", t)
+	debug("Archiver.saveTree", "saveTree(%v)\n", t)
 	var wg sync.WaitGroup
 
 	// add all blobs to global map
@@ -286,7 +286,7 @@ func (arch *Archiver) saveTree(t *Tree) (Blob, error) {
 				for _, id := range node.Content {
 					blob, err := t.Map.FindID(id)
 					if err != nil {
-						debug("unable to find storage id for data blob %v", id.Str())
+						debug("Archiver.saveTree", "unable to find storage id for data blob %v", id.Str())
 						arch.Error(node.path, nil, fmt.Errorf("unable to find storage id for data blob %v", id.Str()))
 						removeContent = true
 						t.Map.DeleteID(id)
@@ -295,7 +295,7 @@ func (arch *Archiver) saveTree(t *Tree) (Blob, error) {
 					}
 
 					if ok, err := arch.s.Test(backend.Data, blob.Storage); !ok || err != nil {
-						debug("blob %v not in repository (error is %v)", blob, err)
+						debug("Archiver.saveTree", "blob %v not in repository (error is %v)", blob, err)
 						arch.Error(node.path, nil, fmt.Errorf("blob %v not in repository (error is %v)", blob.Storage.Str(), err))
 						removeContent = true
 						t.Map.DeleteID(id)
@@ -304,7 +304,7 @@ func (arch *Archiver) saveTree(t *Tree) (Blob, error) {
 				}
 
 				if removeContent {
-					debug("removing content for %s", node.path)
+					debug("Archiver.saveTree", "removing content for %s", node.path)
 					node.Content = node.Content[:0]
 				}
 			}
@@ -370,7 +370,7 @@ func (arch *Archiver) saveTree(t *Tree) (Blob, error) {
 	after := len(t.Map.IDs())
 
 	if before != after {
-		debug("pruned %d ids from map for tree %v\n", before-after, t)
+		debug("Archiver.saveTree", "pruned %d ids from map for tree %v\n", before-after, t)
 	}
 
 	blob, err := arch.SaveTreeJSON(t)
@@ -382,6 +382,8 @@ func (arch *Archiver) saveTree(t *Tree) (Blob, error) {
 }
 
 func (arch *Archiver) Snapshot(dir string, t *Tree, parentSnapshot backend.ID) (*Snapshot, backend.ID, error) {
+	debug_break("Archiver.Snapshot")
+
 	arch.p.Start()
 	defer arch.p.Done()
 

debug.go

@@ -4,33 +4,131 @@ package restic
 
 import (
 	"fmt"
-	"io"
 	"log"
 	"os"
+	"path"
 	"path/filepath"
+	"runtime"
+	"strings"
+	"syscall"
 	"time"
 )
 
 var debugLogger = initDebugLogger()
+var debugTags = make(map[string]bool)
+var debugBreak = make(map[string]bool)
 
 func initDebugLogger() *log.Logger {
 	// create new log file
 	filename := fmt.Sprintf("restic-lib-debug-%d-%s",
 		os.Getpid(), time.Now().Format("20060201-150405"))
-	path := filepath.Join(os.TempDir(), filename)
-	f, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE, 0600)
+	debugfile := filepath.Join(os.TempDir(), filename)
+	f, err := os.OpenFile(debugfile, os.O_WRONLY|os.O_CREATE, 0600)
 	if err != nil {
 		fmt.Fprintf(os.Stderr, "unable to create debug log file: %v", err)
 		os.Exit(2)
 	}
 
 	// open logger
-	l := log.New(io.MultiWriter(os.Stderr, f), "DEBUG: ", log.LstdFlags)
-	fmt.Fprintf(os.Stderr, "debug log for restic library activated, writing log file %s\n", path)
+	l := log.New(f, "DEBUG: ", log.LstdFlags)
+	fmt.Fprintf(os.Stderr, "debug log for restic library activated, writing log file %s\n", debugfile)
+
+	// defaults
+	debugTags["break"] = true
+
+	// initialize tags
+	env := os.Getenv("DEBUG_TAGS")
+	if len(env) > 0 {
+		tags := []string{}
+
+		for _, tag := range strings.Split(env, ",") {
+			t := strings.TrimSpace(tag)
+			val := true
+			if t[0] == '-' {
+				val = false
+				t = t[1:]
+			} else if t[0] == '+' {
+				val = true
+				t = t[1:]
+			}
+
+			// test pattern
+			_, err := path.Match(t, "")
+			if err != nil {
+				fmt.Fprintf(os.Stderr, "error: invalid pattern %q: %v\n", t, err)
+				os.Exit(5)
+			}
+
+			debugTags[t] = val
+			tags = append(tags, tag)
+		}
+
+		fmt.Fprintf(os.Stderr, "debug log enabled for: %v\n", tags)
+	}
+
+	// initialize break tags
+	env = os.Getenv("DEBUG_BREAK")
+	if len(env) > 0 {
+		breaks := []string{}
+
+		for _, tag := range strings.Split(env, ",") {
+			t := strings.TrimSpace(tag)
+			debugBreak[t] = true
+			breaks = append(breaks, t)
+		}
+
+		fmt.Fprintf(os.Stderr, "debug breaks enabled for: %v\n", breaks)
+	}
 
 	return l
 }
 
-func debug(fmt string, args ...interface{}) {
-	debugLogger.Printf(fmt, args...)
+func debug(tag string, f string, args ...interface{}) {
+	dbgprint := func() {
+		fmt.Fprintf(os.Stderr, tag+": "+f, args...)
+	}
+
+	debugLogger.Printf(f, args...)
+
+	// check if tag is enabled directly
+	if v, ok := debugTags[tag]; ok {
+		if v {
+			dbgprint()
+		}
+		return
+	}
+
+	// check for globbing
+	for k, v := range debugTags {
+		if m, _ := path.Match(k, tag); m {
+			if v {
+				dbgprint()
+			}
+			return
+		}
+	}
+
+	// check if tag "all" is enabled
+	if v, ok := debugTags["all"]; ok && v {
+		dbgprint()
+	}
+}
+
+func debug_break(tag string) {
+	// check if breaking is enabled
+	if v, ok := debugBreak[tag]; !ok || !v {
+		return
+	}
+
+	_, file, line, _ := runtime.Caller(1)
+	debug("break", "stopping process %d at %s (%v:%v)\n", os.Getpid(), tag, file, line)
+	p, err := os.FindProcess(os.Getpid())
+	if err != nil {
+		panic(err)
+	}
+
+	err = p.Signal(syscall.SIGSTOP)
+	if err != nil {
+		panic(err)
+	}
 }

debug_release.go

@@ -2,4 +2,6 @@
 
 package restic
 
-func debug(fmt string, args ...interface{}) {}
+func debug(tag string, fmt string, args ...interface{}) {}
+
+func debug_break(string) {}

map.go

@@ -85,7 +85,7 @@ func (bl *Map) Insert(blob Blob) Blob {
 	bl.m.Lock()
 	defer bl.m.Unlock()
 
-	debug("  Map<%p> insert %v", bl, blob)
+	debug("Map.Insert", "  Map<%p> insert %v", bl, blob)
 
 	return bl.insert(blob)
 }

tree.go

@@ -127,7 +127,7 @@ func LoadTreeRecursive(path string, s Server, blob Blob) (*Tree, error) {
 
 // CopyFrom recursively copies all content from other to t.
 func (t Tree) CopyFrom(other *Tree, s *Server) error {
-	debug("CopyFrom(%v)\n", other)
+	debug("Tree.CopyFrom", "CopyFrom(%v)\n", other)
 	for _, node := range t.Nodes {
 		// only process files and dirs
 		if node.Type != "file" && node.Type != "dir" {
@@ -139,14 +139,14 @@ func (t Tree) CopyFrom(other *Tree, s *Server) error {
 
 		// if the node could not be found or the type has changed, proceed to the next
 		if err == ErrNodeNotFound || node.Type != oldNode.Type {
-			debug("  node %v is new\n", node)
+			debug("Tree.CopyFrom", "  node %v is new\n", node)
 			continue
 		}
 
 		if node.Type == "file" {
 			// compare content
 			if node.SameContent(oldNode) {
-				debug("  file node %v has same content\n", node)
+				debug("Tree.CopyFrom", "  file node %v has same content\n", node)
 
 				// check if all content is still available in the repository
 				for _, id := range oldNode.Content {
@@ -170,7 +170,7 @@ func (t Tree) CopyFrom(other *Tree, s *Server) error {
 						return err
 					}
 
-					debug("    insert blob %v\n", blob)
+					debug("Tree.CopyFrom", "    insert blob %v\n", blob)
 					t.Map.Insert(blob)
 				}
 			}
@@ -183,7 +183,7 @@ func (t Tree) CopyFrom(other *Tree, s *Server) error {
 
 			// check if tree has changed
 			if node.tree.Equals(*oldNode.tree) {
-				debug("  tree node %v has same content\n", node)
+				debug("Tree.CopyFrom", "  tree node %v has same content\n", node)
 
 				// if nothing has changed, copy subtree ID
 				node.Subtree = oldNode.Subtree
@@ -194,12 +194,12 @@ func (t Tree) CopyFrom(other *Tree, s *Server) error {
 					return err
 				}
 
-				debug("    insert blob %v\n", blob)
+				debug("Tree.CopyFrom", "    insert blob %v\n", blob)
 				t.Map.Insert(blob)
 			} else {
-				debug("  trees are not equal: %v\n", node)
-				debug("    %#v\n", node.tree)
-				debug("    %#v\n", oldNode.tree)
+				debug("Tree.CopyFrom", "  trees are not equal: %v\n", node)
+				debug("Tree.CopyFrom", "    %#v\n", node.tree)
+				debug("Tree.CopyFrom", "    %#v\n", oldNode.tree)
 			}
 		}
 	}
@@ -210,20 +210,20 @@ func (t Tree) CopyFrom(other *Tree, s *Server) error {
 // Equals returns true if t and other have exactly the same nodes and map.
 func (t Tree) Equals(other Tree) bool {
 	if len(t.Nodes) != len(other.Nodes) {
-		debug("tree.Equals(): trees have different number of nodes")
+		debug("Tree.Equals", "tree.Equals(): trees have different number of nodes")
 		return false
 	}
 
 	if !t.Map.Equals(other.Map) {
-		debug("tree.Equals(): maps aren't equal")
+		debug("Tree.Equals", "tree.Equals(): maps aren't equal")
 		return false
 	}
 
 	for i := 0; i < len(t.Nodes); i++ {
 		if !t.Nodes[i].Equals(*other.Nodes[i]) {
-			debug("tree.Equals(): node %d is different:", i)
-			debug("  %#v", t.Nodes[i])
-			debug("  %#v", other.Nodes[i])
+			debug("Tree.Equals", "tree.Equals(): node %d is different:", i)
+			debug("Tree.Equals", "  %#v", t.Nodes[i])
+			debug("Tree.Equals", "  %#v", other.Nodes[i])
 			return false
 		}
 	}