From 48751e193569cdedbbd8cd94c9c4e229c6566de7 Mon Sep 17 00:00:00 2001 From: Alexander Neumann Date: Sun, 11 Jan 2015 14:09:44 +0100 Subject: [PATCH] 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 | 20 +++++---- debug.go | 112 ++++++++++++++++++++++++++++++++++++++++++++--- debug_release.go | 4 +- map.go | 2 +- tree.go | 28 ++++++------ 5 files changed, 134 insertions(+), 32 deletions(-) diff --git a/archiver.go b/archiver.go index 5ab757adb..8a4760115 100644 --- a/archiver.go +++ b/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() diff --git a/debug.go b/debug.go index 2e51cc2f9..d6dff581a 100644 --- a/debug.go +++ b/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) + } } diff --git a/debug_release.go b/debug_release.go index d49429aa9..b49a2440b 100644 --- a/debug_release.go +++ b/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) {} diff --git a/map.go b/map.go index 99db34bea..5e1566418 100644 --- a/map.go +++ b/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) } diff --git a/tree.go b/tree.go index fa3117897..ea07b7d22 100644 --- a/tree.go +++ b/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 } }