From 2553ba0463ceefbabe848e00d98b6872f4c9745b Mon Sep 17 00:00:00 2001 From: Jakob Borg Date: Sun, 9 Mar 2014 09:15:36 +0100 Subject: [PATCH] Discover & main tracing --- cmd/syncthing/debug.go | 15 +++++++++ cmd/syncthing/filemonitor.go | 9 +++--- cmd/syncthing/main.go | 31 ++++++++---------- cmd/syncthing/model.go | 63 +++++++++++++++++------------------- discover/debug.go | 12 +++++++ 5 files changed, 73 insertions(+), 57 deletions(-) create mode 100644 cmd/syncthing/debug.go create mode 100644 discover/debug.go diff --git a/cmd/syncthing/debug.go b/cmd/syncthing/debug.go new file mode 100644 index 00000000..dd53ec0e --- /dev/null +++ b/cmd/syncthing/debug.go @@ -0,0 +1,15 @@ +package main + +import ( + "log" + "os" + "strings" +) + +var ( + dlog = log.New(os.Stderr, "main: ", log.Lmicroseconds|log.Lshortfile) + debugNet = strings.Contains(os.Getenv("STTRACE"), "net") + debugIdx = strings.Contains(os.Getenv("STTRACE"), "idx") + debugNeed = strings.Contains(os.Getenv("STTRACE"), "need") + debugPull = strings.Contains(os.Getenv("STTRACE"), "pull") +) diff --git a/cmd/syncthing/filemonitor.go b/cmd/syncthing/filemonitor.go index 507c4380..a86506c3 100644 --- a/cmd/syncthing/filemonitor.go +++ b/cmd/syncthing/filemonitor.go @@ -4,7 +4,6 @@ import ( "bytes" "errors" "fmt" - "log" "os" "path" "sync" @@ -26,8 +25,8 @@ type fileMonitor struct { } func (m *fileMonitor) FileBegins(cc <-chan content) error { - if m.model.trace["file"] { - log.Printf("FILE: FileBegins: " + m.name) + if debugPull { + dlog.Println("file begins:", m.name) } tmp := defTempNamer.TempName(m.path) @@ -110,8 +109,8 @@ func (m *fileMonitor) copyRemoteBlocks(cc <-chan content, outFile *os.File, writ } func (m *fileMonitor) FileDone() error { - if m.model.trace["file"] { - log.Printf("FILE: FileDone: " + m.name) + if debugPull { + dlog.Println("file done:", m.name) } m.writeDone.Wait() diff --git a/cmd/syncthing/main.go b/cmd/syncthing/main.go index e1af5da0..27011de3 100644 --- a/cmd/syncthing/main.go +++ b/cmd/syncthing/main.go @@ -36,7 +36,6 @@ var ( var ( showVersion bool confDir string - trace string verbose bool ) @@ -50,12 +49,15 @@ const ( STTRACE A comma separated string of facilities to trace. The valid facility strings: - "scanner" (the file change scanner) - - "discover" (the node discovery package)` + - "discover" (the node discovery package) + - "net" (connecting and disconnecting, sent/received messages) + - "idx" (index sending and receiving) + - "need" (file need calculations) + - "pull" (file pull activity)` ) func main() { flag.StringVar(&confDir, "home", getDefaultConfDir(), "Set configuration directory") - flag.StringVar(&trace, "debug.trace", "", "(connect,net,idx,file,pull)") flag.BoolVar(&showVersion, "version", false, "Show version") flag.BoolVar(&verbose, "v", false, "Be more verbose") flag.Usage = usageFor(flag.CommandLine, usage, extraUsage) @@ -79,10 +81,6 @@ func main() { runtime.GOMAXPROCS(runtime.NumCPU()) } - if len(trace) > 0 { - log.SetFlags(log.Lshortfile | log.Ldate | log.Ltime | log.Lmicroseconds) - logger.SetFlags(log.Lshortfile | log.Ldate | log.Ltime | log.Lmicroseconds) - } confDir = expandTilde(confDir) // Ensure that our home directory exists and that we have a certificate and key. @@ -192,9 +190,6 @@ func main() { ensureDir(dir, -1) m := NewModel(dir, cfg.Options.MaxChangeKbps*1000) - for _, t := range strings.Split(trace, ",") { - m.Trace(t) - } if cfg.Options.MaxSendKbps > 0 { m.LimitRate(cfg.Options.MaxSendKbps) } @@ -397,8 +392,8 @@ func printStatsLoop(m *Model) { } func listen(myID string, addr string, m *Model, tlsCfg *tls.Config, connOpts map[string]string) { - if strings.Contains(trace, "connect") { - debugln("NET: Listening on", addr) + if debugNet { + dlog.Println("listening on", addr) } l, err := tls.Listen("tcp", addr, tlsCfg) fatalErr(err) @@ -411,8 +406,8 @@ listen: continue } - if strings.Contains(trace, "connect") { - debugln("NET: Connect from", conn.RemoteAddr()) + if debugNet { + dlog.Println("connect from", conn.RemoteAddr()) } tc := conn.(*tls.Conn) @@ -493,13 +488,13 @@ func connect(myID string, disc *discover.Discoverer, m *Model, tlsCfg *tls.Confi } } - if strings.Contains(trace, "connect") { - debugln("NET: Dial", nodeCfg.NodeID, addr) + if debugNet { + dlog.Println("dial", nodeCfg.NodeID, addr) } conn, err := tls.Dial("tcp", addr, tlsCfg) if err != nil { - if strings.Contains(trace, "connect") { - debugln("NET:", err) + if debugNet { + dlog.Println(err) } continue } diff --git a/cmd/syncthing/model.go b/cmd/syncthing/model.go index f8a4af86..b705508a 100644 --- a/cmd/syncthing/model.go +++ b/cmd/syncthing/model.go @@ -44,8 +44,6 @@ type Model struct { delete bool initmut sync.Mutex // protects rwRunning and delete - trace map[string]bool - sup suppressor parallelRequests int @@ -84,7 +82,6 @@ func NewModel(dir string, maxChangeBw int) *Model { protoConn: make(map[string]Connection), rawConn: make(map[string]io.Closer), lastIdxBcast: time.Now(), - trace: make(map[string]bool), sup: suppressor{threshold: int64(maxChangeBw)}, fq: NewFileQueue(), dq: make(chan scanner.File), @@ -109,11 +106,6 @@ func (m *Model) LimitRate(kbps int) { }() } -// Trace enables trace logging of the given facility. This is a debugging function; grep for m.trace. -func (m *Model) Trace(t string) { - m.trace[t] = true -} - // StartRW starts read/write processing on the current model. When in // read/write mode the model will attempt to keep in sync with the cluster by // pulling needed files from peer nodes. @@ -286,8 +278,8 @@ func (m *Model) Index(nodeID string, fs []protocol.FileInfo) { m.imut.Lock() defer m.imut.Unlock() - if m.trace["net"] { - debugf("NET IDX(in): %s: %d files", nodeID, len(fs)) + if debugNet { + dlog.Printf("IDX(in): %s: %d files", nodeID, len(fs)) } repo := make(map[string]scanner.File) @@ -314,8 +306,8 @@ func (m *Model) IndexUpdate(nodeID string, fs []protocol.FileInfo) { m.imut.Lock() defer m.imut.Unlock() - if m.trace["net"] { - debugf("NET IDXUP(in): %s: %d files", nodeID, len(files)) + if debugNet { + dlog.Printf("IDXUP(in): %s: %d files", nodeID, len(files)) } m.rmut.Lock() @@ -336,12 +328,12 @@ func (m *Model) IndexUpdate(nodeID string, fs []protocol.FileInfo) { } func (m *Model) indexUpdate(repo map[string]scanner.File, f scanner.File) { - if m.trace["idx"] { + if debugIdx { var flagComment string if f.Flags&protocol.FlagDeleted != 0 { flagComment = " (deleted)" } - debugf("IDX(in): %q m=%d f=%o%s v=%d (%d blocks)", f.Name, f.Modified, f.Flags, flagComment, f.Version, len(f.Blocks)) + dlog.Printf("IDX(in): %q m=%d f=%o%s v=%d (%d blocks)", f.Name, f.Modified, f.Flags, flagComment, f.Version, len(f.Blocks)) } if extraFlags := f.Flags &^ (protocol.FlagInvalid | protocol.FlagDeleted | 0xfff); extraFlags != 0 { @@ -355,8 +347,8 @@ func (m *Model) indexUpdate(repo map[string]scanner.File, f scanner.File) { // Close removes the peer from the model and closes the underlying connection if possible. // Implements the protocol.Model interface. func (m *Model) Close(node string, err error) { - if m.trace["net"] { - debugf("NET: %s: %v", node, err) + if debugNet { + dlog.Printf("%s: %v", node, err) } if err == protocol.ErrClusterHash { warnf("Connection to %s closed due to mismatched cluster hash. Ensure that the configured cluster members are identical on both nodes.", node) @@ -405,8 +397,8 @@ func (m *Model) Request(nodeID, repo, name string, offset int64, size int) ([]by return nil, ErrInvalid } - if m.trace["net"] && nodeID != "" { - debugf("NET REQ(in): %s: %q o=%d s=%d", nodeID, name, offset, size) + if debugNet && nodeID != "" { + dlog.Printf("REQ(in): %s: %q o=%d s=%d", nodeID, name, offset, size) } fn := path.Join(m.dir, name) fd, err := os.Open(fn) // XXX: Inefficient, should cache fd? @@ -509,6 +501,9 @@ func (m *Model) AddConnection(rawConn io.Closer, protoConn Connection) { go func() { idx := m.ProtocolIndex() + if debugNet { + dlog.Printf("IDX(out/initial): %s: %d files", nodeID, len(idx)) + } protoConn.Index("default", idx) }() @@ -522,14 +517,14 @@ func (m *Model) AddConnection(rawConn io.Closer, protoConn Connection) { for i := 0; i < m.parallelRequests; i++ { i := i go func() { - if m.trace["pull"] { - debugln("PULL: Starting", nodeID, i) + if debugPull { + dlog.Println("starting puller:", nodeID, i) } for { m.pmut.RLock() if _, ok := m.protoConn[nodeID]; !ok { - if m.trace["pull"] { - debugln("PULL: Exiting", nodeID, i) + if debugPull { + dlog.Println("stopping puller:", nodeID, i) } m.pmut.RUnlock() return @@ -538,8 +533,8 @@ func (m *Model) AddConnection(rawConn io.Closer, protoConn Connection) { qb, ok := m.fq.Get(nodeID) if ok { - if m.trace["pull"] { - debugln("PULL: Request", nodeID, i, qb.name, qb.block.Offset) + if debugPull { + dlog.Println("request: out", nodeID, i, qb.name, qb.block.Offset) } data, _ := protoConn.Request("default", qb.name, qb.block.Offset, int(qb.block.Size)) m.fq.Done(qb.name, qb.block.Offset, data) @@ -560,12 +555,12 @@ func (m *Model) ProtocolIndex() []protocol.FileInfo { for _, f := range m.local { mf := fileInfoFromFile(f) - if m.trace["idx"] { + if debugIdx { var flagComment string if mf.Flags&protocol.FlagDeleted != 0 { flagComment = " (deleted)" } - debugf("IDX(out): %q m=%d f=%o%s v=%d (%d blocks)", mf.Name, mf.Modified, mf.Flags, flagComment, mf.Version, len(mf.Blocks)) + dlog.Printf("IDX(out): %q m=%d f=%o%s v=%d (%d blocks)", mf.Name, mf.Modified, mf.Flags, flagComment, mf.Version, len(mf.Blocks)) } index = append(index, mf) } @@ -583,8 +578,8 @@ func (m *Model) requestGlobal(nodeID, name string, offset int64, size int, hash return nil, fmt.Errorf("requestGlobal: no such node: %s", nodeID) } - if m.trace["net"] { - debugf("NET REQ(out): %s: %q o=%d s=%d h=%x", nodeID, name, offset, size, hash) + if debugNet { + dlog.Printf("REQ(out): %s: %q o=%d s=%d h=%x", nodeID, name, offset, size, hash) } return nc.Request("default", name, offset, size) @@ -611,8 +606,8 @@ func (m *Model) broadcastIndexLoop() { m.pmut.RLock() for _, node := range m.protoConn { node := node - if m.trace["net"] { - debugf("NET IDX(out/loop): %s: %d files", node.ID(), len(idx)) + if debugNet { + dlog.Printf("IDX(out/loop): %s: %d files", node.ID(), len(idx)) } go func() { node.Index("default", idx) @@ -823,8 +818,8 @@ func (m *Model) recomputeNeedForFile(gf scanner.File, toAdd []addOrder, toDelete // Don't have the file, so don't need to delete it return toAdd, toDelete } - if m.trace["need"] { - debugf("NEED: lf:%v gf:%v", lf, gf) + if debugNeed { + dlog.Printf("need: lf:%v gf:%v", lf, gf) } if gf.Flags&protocol.FlagDeleted != 0 { @@ -865,8 +860,8 @@ func (m *Model) WhoHas(name string) []string { func (m *Model) deleteLoop() { for file := range m.dq { - if m.trace["file"] { - debugln("FILE: Delete", file.Name) + if debugPull { + dlog.Println("delete", file.Name) } path := path.Clean(path.Join(m.dir, file.Name)) err := os.Remove(path) diff --git a/discover/debug.go b/discover/debug.go new file mode 100644 index 00000000..18de7027 --- /dev/null +++ b/discover/debug.go @@ -0,0 +1,12 @@ +package discover + +import ( + "log" + "os" + "strings" +) + +var ( + dlog = log.New(os.Stderr, "discover: ", log.Lmicroseconds|log.Lshortfile) + debug = strings.Contains(os.Getenv("STTRACE"), "discover") +)