From fb312a71f743cbcadaec7ba76bbb941d79c9c430 Mon Sep 17 00:00:00 2001 From: Jakob Borg Date: Thu, 30 Apr 2015 20:21:48 +0200 Subject: [PATCH] Add verbose logging (fixes #179) --- Godeps/Godeps.json | 2 +- .../src/github.com/calmh/logger/logger.go | 19 +++ cmd/syncthing/main.go | 6 + cmd/syncthing/verbose.go | 126 ++++++++++++++++++ 4 files changed, 152 insertions(+), 1 deletion(-) create mode 100644 cmd/syncthing/verbose.go diff --git a/Godeps/Godeps.json b/Godeps/Godeps.json index 1886f33d4..3ab1e1849 100644 --- a/Godeps/Godeps.json +++ b/Godeps/Godeps.json @@ -11,7 +11,7 @@ }, { "ImportPath": "github.com/calmh/logger", - "Rev": "f50d32b313bec2933a3e1049f7416a29f3413d29" + "Rev": "4d4e2801954c5581e4c2a80a3d3beb3b3645fd04" }, { "ImportPath": "github.com/calmh/luhn", diff --git a/Godeps/_workspace/src/github.com/calmh/logger/logger.go b/Godeps/_workspace/src/github.com/calmh/logger/logger.go index 103021bfc..060e63b3a 100644 --- a/Godeps/_workspace/src/github.com/calmh/logger/logger.go +++ b/Godeps/_workspace/src/github.com/calmh/logger/logger.go @@ -16,6 +16,7 @@ type LogLevel int const ( LevelDebug LogLevel = iota + LevelVerbose LevelInfo LevelOK LevelWarn @@ -83,6 +84,24 @@ func (l *Logger) Debugf(format string, vals ...interface{}) { l.callHandlers(LevelDebug, s) } +// Infoln logs a line with a VERBOSE prefix. +func (l *Logger) Verboseln(vals ...interface{}) { + l.mut.Lock() + defer l.mut.Unlock() + s := fmt.Sprintln(vals...) + l.logger.Output(2, "VERBOSE: "+s) + l.callHandlers(LevelVerbose, s) +} + +// Infof logs a formatted line with a VERBOSE prefix. +func (l *Logger) Verbosef(format string, vals ...interface{}) { + l.mut.Lock() + defer l.mut.Unlock() + s := fmt.Sprintf(format, vals...) + l.logger.Output(2, "VERBOSE: "+s) + l.callHandlers(LevelVerbose, s) +} + // Infoln logs a line with an INFO prefix. func (l *Logger) Infoln(vals ...interface{}) { l.mut.Lock() diff --git a/cmd/syncthing/main.go b/cmd/syncthing/main.go index 3153fc0ec..e88f789c1 100644 --- a/cmd/syncthing/main.go +++ b/cmd/syncthing/main.go @@ -194,6 +194,7 @@ var ( generateDir string logFile string auditEnabled bool + verbose bool noRestart = os.Getenv("STNORESTART") != "" noUpgrade = os.Getenv("STNOUPGRADE") != "" guiAddress = os.Getenv("STGUIADDRESS") // legacy @@ -231,6 +232,7 @@ func main() { flag.BoolVar(&showVersion, "version", false, "Show version") flag.StringVar(&upgradeTo, "upgrade-to", upgradeTo, "Force upgrade directly from specified URL") flag.BoolVar(&auditEnabled, "audit", false, "Write events to audit file") + flag.BoolVar(&verbose, "verbose", false, "Print verbose log output") flag.Usage = usageFor(flag.CommandLine, usage, fmt.Sprintf(extraUsage, baseDirs["config"])) flag.Parse() @@ -391,6 +393,10 @@ func syncthingMain() { startAuditing(mainSvc) } + if verbose { + mainSvc.Add(newVerboseSvc()) + } + if len(os.Getenv("GOMAXPROCS")) == 0 { runtime.GOMAXPROCS(runtime.NumCPU()) } diff --git a/cmd/syncthing/verbose.go b/cmd/syncthing/verbose.go new file mode 100644 index 000000000..6b1b4b173 --- /dev/null +++ b/cmd/syncthing/verbose.go @@ -0,0 +1,126 @@ +// Copyright (C) 2015 The Syncthing Authors. +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this file, +// You can obtain one at http://mozilla.org/MPL/2.0/. + +package main + +import ( + "fmt" + + "github.com/syncthing/syncthing/internal/events" +) + +// The verbose logging service subscribes to events and prints these in +// verbose format to the console using INFO level. +type verboseSvc struct { + stop chan struct{} // signals time to stop + started chan struct{} // signals startup complete +} + +func newVerboseSvc() *verboseSvc { + return &verboseSvc{ + stop: make(chan struct{}), + started: make(chan struct{}), + } +} + +// Serve runs the verbose logging service. +func (s *verboseSvc) Serve() { + sub := events.Default.Subscribe(events.AllEvents) + defer events.Default.Unsubscribe(sub) + + // We're ready to start processing events. + close(s.started) + + for { + select { + case ev := <-sub.C(): + formatted := s.formatEvent(ev) + if formatted != "" { + l.Verboseln(formatted) + } + case <-s.stop: + return + } + } +} + +// Stop stops the verbose logging service. +func (s *verboseSvc) Stop() { + close(s.stop) +} + +// WaitForStart returns once the verbose logging service is ready to receive +// events, or immediately if it's already running. +func (s *verboseSvc) WaitForStart() { + <-s.started +} + +func (s *verboseSvc) formatEvent(ev events.Event) string { + switch ev.Type { + case events.Ping, events.DownloadProgress: + // Skip + return "" + + case events.Starting: + return fmt.Sprintf("Starting up (%s)", ev.Data.(map[string]string)["home"]) + case events.StartupComplete: + return "Startup complete" + + case events.DeviceDiscovered: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Discovered device %v at %v", data["device"], data["addrs"]) + case events.DeviceConnected: + data := ev.Data.(map[string]string) + return fmt.Sprintf("Connected to device %v at %v", data["id"], data["addr"]) + case events.DeviceDisconnected: + data := ev.Data.(map[string]string) + return fmt.Sprintf("Disconnected from device %v", data["id"]) + + case events.StateChanged: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Folder %q is now %v", data["folder"], data["to"]) + + case events.RemoteIndexUpdated: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Device %v sent an index update for %q with %d items", data["device"], data["folder"], data["items"]) + case events.LocalIndexUpdated: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Updated index for folder %q with %v items", data["folder"], data["items"]) + + case events.DeviceRejected: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Rejected connection from device %v at %v", data["device"], data["address"]) + case events.FolderRejected: + data := ev.Data.(map[string]string) + return fmt.Sprintf("Rejected unshared folder %q from device %v", data["folder"], data["device"]) + + case events.ItemStarted: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Started syncing %q / %q (%v %v)", data["folder"], data["item"], data["action"], data["type"]) + case events.ItemFinished: + data := ev.Data.(map[string]interface{}) + if err := data["err"]; err != nil { + return fmt.Sprintf("Finished syncing %q / %q (%v %v): %v", data["folder"], data["item"], data["action"], data["type"], err) + } + return fmt.Sprintf("Finished syncing %q / %q (%v %v): Success", data["folder"], data["item"], data["action"], data["type"]) + + case events.ConfigSaved: + return "Configuration was saved" + + case events.FolderCompletion: + data := ev.Data.(map[string]interface{}) + return fmt.Sprintf("Completion for folder %q on device %v is %v%%", data["folder"], data["device"], data["completion"]) + case events.FolderSummary: + data := ev.Data.(map[string]interface{}) + sum := data["summary"].(map[string]interface{}) + delete(sum, "invalid") + delete(sum, "ignorePatterns") + delete(sum, "stateChanged") + return fmt.Sprintf("Summary for folder %q is %v", data["folder"], data["summary"]) + } + + return fmt.Sprintf("%s %#v", ev.Type, ev) +}