Add verbose logging (fixes #179)

Godeps/Godeps.json

@@ -11,7 +11,7 @@
 		},
 		{
 			"ImportPath": "github.com/calmh/logger",
-			"Rev": "f50d32b313bec2933a3e1049f7416a29f3413d29"
+			"Rev": "4d4e2801954c5581e4c2a80a3d3beb3b3645fd04"
 		},
 		{
 			"ImportPath": "github.com/calmh/luhn",

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()

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())
 	}

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)
+}