Implement facility based logger, debugging via REST API

This implements a new debug/trace infrastructure based on a slightly
hacked up logger. Instead of the traditional "if debug { ... }" I've
rewritten the logger to have no-op Debugln and Debugf, unless debugging
has been enabled for a given "facility". The "facility" is just a
string, typically a package name.

This will be slightly slower than before; but not that much as it's
mostly a function call that returns immediately. For the cases where it
matters (the Debugln takes a hex.Dump() of something for example, and
it's not in a very occasional "if err != nil" branch) there is an
l.ShouldDebug(facility) that is fast enough to be used like the old "if
debug".

The point of all this is that we can now toggle debugging for the
various packages on and off at runtime. There's a new method
/rest/system/debug that can be POSTed a set of facilities to enable and
disable debug for, or GET from to get a list of facilities with
descriptions and their current debug status.

Similarly a /rest/system/log?since=... can grab the latest log entries,
up to 250 of them (hardcoded constant in main.go) plus the initial few.

Not implemented in this commit (but planned) is a simple debug GUI
available on /debug that shows the current log in an easily pasteable
format and has checkboxes to enable the various debug facilities.

The debug instructions to a user then becomes "visit this URL, check
these boxes, reproduce your problem, copy and paste the log". The actual
log viewer on the hypothetical /debug URL can poll regularly for new log
entries and this bypass the 250 line limit.

The existing STTRACE=foo variable is still obeyed and just sets the
start state of the system.

cmd/syncthing/debug.go

@@ -9,10 +9,24 @@ package main
 import (
 	"os"
 	"strings"
+
+	"github.com/syncthing/syncthing/lib/logger"
 )
 
 var (
-	debugNet    = strings.Contains(os.Getenv("STTRACE"), "net") || os.Getenv("STTRACE") == "all"
-	debugHTTP   = strings.Contains(os.Getenv("STTRACE"), "http") || os.Getenv("STTRACE") == "all"
-	debugSuture = strings.Contains(os.Getenv("STTRACE"), "suture") || os.Getenv("STTRACE") == "all"
+	l     = logger.DefaultLogger.NewFacility("main", "Main package")
+	httpl = logger.DefaultLogger.NewFacility("http", "REST API")
 )
+
+func init() {
+	l.SetDebug("main", strings.Contains(os.Getenv("STTRACE"), "main") || os.Getenv("STTRACE") == "all")
+	l.SetDebug("http", strings.Contains(os.Getenv("STTRACE"), "http") || os.Getenv("STTRACE") == "all")
+}
+
+func shouldDebugMain() bool {
+	return l.ShouldDebug("main")
+}
+
+func shouldDebugHTTP() bool {
+	return l.ShouldDebug("http")
+}

cmd/syncthing/gui.go

@@ -20,16 +20,17 @@ import (
 	"path/filepath"
 	"reflect"
 	"runtime"
+	"sort"
 	"strconv"
 	"strings"
 	"time"
 
-	"github.com/calmh/logger"
 	"github.com/syncthing/syncthing/lib/auto"
 	"github.com/syncthing/syncthing/lib/config"
 	"github.com/syncthing/syncthing/lib/db"
 	"github.com/syncthing/syncthing/lib/discover"
 	"github.com/syncthing/syncthing/lib/events"
+	"github.com/syncthing/syncthing/lib/logger"
 	"github.com/syncthing/syncthing/lib/model"
 	"github.com/syncthing/syncthing/lib/osutil"
 	"github.com/syncthing/syncthing/lib/protocol"
@@ -41,15 +42,8 @@ import (
 	"golang.org/x/crypto/bcrypt"
 )
 
-type guiError struct {
-	Time  time.Time `json:"time"`
-	Error string    `json:"error"`
-}
-
 var (
 	configInSync = true
-	guiErrors    = []guiError{}
-	guiErrorsMut = sync.NewMutex()
 	startTime    = time.Now()
 )
 
@@ -65,9 +59,12 @@ type apiSvc struct {
 	fss             *folderSummarySvc
 	stop            chan struct{}
 	systemConfigMut sync.Mutex
+
+	guiErrors *logger.Recorder
+	systemLog *logger.Recorder
 }
 
-func newAPISvc(id protocol.DeviceID, cfg *config.Wrapper, assetDir string, m *model.Model, eventSub *events.BufferedSubscription, discoverer *discover.CachingMux, relaySvc *relay.Svc) (*apiSvc, error) {
+func newAPISvc(id protocol.DeviceID, cfg *config.Wrapper, assetDir string, m *model.Model, eventSub *events.BufferedSubscription, discoverer *discover.CachingMux, relaySvc *relay.Svc, errors, systemLog *logger.Recorder) (*apiSvc, error) {
 	svc := &apiSvc{
 		id:              id,
 		cfg:             cfg,
@@ -77,6 +74,8 @@ func newAPISvc(id protocol.DeviceID, cfg *config.Wrapper, assetDir string, m *mo
 		discoverer:      discoverer,
 		relaySvc:        relaySvc,
 		systemConfigMut: sync.NewMutex(),
+		guiErrors:       errors,
+		systemLog:       systemLog,
 	}
 
 	var err error
@@ -138,8 +137,6 @@ func (s *apiSvc) getListener(cfg config.GUIConfiguration) (net.Listener, error)
 func (s *apiSvc) Serve() {
 	s.stop = make(chan struct{})
 
-	l.AddHandler(logger.LevelWarn, s.showGuiError)
-
 	// The GET handlers
 	getRestMux := http.NewServeMux()
 	getRestMux.HandleFunc("/rest/db/completion", s.getDBCompletion)              // device folder
@@ -164,6 +161,9 @@ func (s *apiSvc) Serve() {
 	getRestMux.HandleFunc("/rest/system/status", s.getSystemStatus)              // -
 	getRestMux.HandleFunc("/rest/system/upgrade", s.getSystemUpgrade)            // -
 	getRestMux.HandleFunc("/rest/system/version", s.getSystemVersion)            // -
+	getRestMux.HandleFunc("/rest/system/debug", s.getSystemDebug)                // -
+	getRestMux.HandleFunc("/rest/system/log", s.getSystemLog)                    // [since]
+	getRestMux.HandleFunc("/rest/system/log.txt", s.getSystemLogTxt)             // [since]
 
 	// The POST handlers
 	postRestMux := http.NewServeMux()
@@ -181,6 +181,7 @@ func (s *apiSvc) Serve() {
 	postRestMux.HandleFunc("/rest/system/upgrade", s.postSystemUpgrade)        // -
 	postRestMux.HandleFunc("/rest/system/pause", s.postSystemPause)            // device
 	postRestMux.HandleFunc("/rest/system/resume", s.postSystemResume)          // device
+	postRestMux.HandleFunc("/rest/system/debug", s.postSystemDebug)            // [enable] [disable]
 
 	// Debug endpoints, not for general use
 	getRestMux.HandleFunc("/rest/debug/peerCompletion", s.getPeerCompletion)
@@ -223,9 +224,7 @@ func (s *apiSvc) Serve() {
 		handler = redirectToHTTPSMiddleware(handler)
 	}
 
-	if debugHTTP {
-		handler = debugMiddleware(handler)
-	}
+	handler = debugMiddleware(handler)
 
 	srv := http.Server{
 		Handler:     handler,
@@ -379,6 +378,36 @@ func (s *apiSvc) getSystemVersion(w http.ResponseWriter, r *http.Request) {
 	})
 }
 
+func (s *apiSvc) getSystemDebug(w http.ResponseWriter, r *http.Request) {
+	w.Header().Set("Content-Type", "application/json; charset=utf-8")
+	names := l.Facilities()
+	enabled := l.FacilityDebugging()
+	sort.Strings(enabled)
+	json.NewEncoder(w).Encode(map[string]interface{}{
+		"facilities": names,
+		"enabled":    enabled,
+	})
+}
+
+func (s *apiSvc) postSystemDebug(w http.ResponseWriter, r *http.Request) {
+	w.Header().Set("Content-Type", "application/json; charset=utf-8")
+	q := r.URL.Query()
+	for _, f := range strings.Split(q.Get("enable"), ",") {
+		if f == "" {
+			continue
+		}
+		l.SetDebug(f, true)
+		l.Infof("Enabled debug data for %q", f)
+	}
+	for _, f := range strings.Split(q.Get("disable"), ",") {
+		if f == "" {
+			continue
+		}
+		l.SetDebug(f, false)
+		l.Infof("Disabled debug data for %q", f)
+	}
+}
+
 func (s *apiSvc) getDBBrowse(w http.ResponseWriter, r *http.Request) {
 	qs := r.URL.Query()
 	folder := qs.Get("folder")
@@ -684,30 +713,41 @@ func (s *apiSvc) getSystemStatus(w http.ResponseWriter, r *http.Request) {
 
 func (s *apiSvc) getSystemError(w http.ResponseWriter, r *http.Request) {
 	w.Header().Set("Content-Type", "application/json; charset=utf-8")
-	guiErrorsMut.Lock()
-	json.NewEncoder(w).Encode(map[string][]guiError{"errors": guiErrors})
-	guiErrorsMut.Unlock()
+	json.NewEncoder(w).Encode(map[string][]logger.Line{
+		"errors": s.guiErrors.Since(time.Time{}),
+	})
 }
 
 func (s *apiSvc) postSystemError(w http.ResponseWriter, r *http.Request) {
 	bs, _ := ioutil.ReadAll(r.Body)
 	r.Body.Close()
-	s.showGuiError(0, string(bs))
+	l.Warnln(string(bs))
 }
 
 func (s *apiSvc) postSystemErrorClear(w http.ResponseWriter, r *http.Request) {
-	guiErrorsMut.Lock()
-	guiErrors = []guiError{}
-	guiErrorsMut.Unlock()
+	s.guiErrors.Clear()
 }
 
-func (s *apiSvc) showGuiError(l logger.LogLevel, err string) {
-	guiErrorsMut.Lock()
-	guiErrors = append(guiErrors, guiError{time.Now(), err})
-	if len(guiErrors) > 5 {
-		guiErrors = guiErrors[len(guiErrors)-5:]
+func (s *apiSvc) getSystemLog(w http.ResponseWriter, r *http.Request) {
+	q := r.URL.Query()
+	since, err := time.Parse(time.RFC3339, q.Get("since"))
+	l.Debugln(err)
+	w.Header().Set("Content-Type", "application/json; charset=utf-8")
+
+	json.NewEncoder(w).Encode(map[string][]logger.Line{
+		"messages": s.systemLog.Since(since),
+	})
+}
+
+func (s *apiSvc) getSystemLogTxt(w http.ResponseWriter, r *http.Request) {
+	q := r.URL.Query()
+	since, err := time.Parse(time.RFC3339, q.Get("since"))
+	l.Debugln(err)
+	w.Header().Set("Content-Type", "text/plain; charset=utf-8")
+
+	for _, line := range s.systemLog.Since(since) {
+		fmt.Fprintf(w, "%s: %s\n", line.When.Format(time.RFC3339), line.Message)
 	}
-	guiErrorsMut.Unlock()
 }
 
 func (s *apiSvc) getSystemDiscovery(w http.ResponseWriter, r *http.Request) {

cmd/syncthing/gui_auth.go

@@ -42,9 +42,7 @@ func basicAuthAndSessionMiddleware(cookieName string, cfg config.GUIConfiguratio
 			}
 		}
 
-		if debugHTTP {
-			l.Debugln("Sessionless HTTP request with authentication; this is expensive.")
-		}
+		httpl.Debugln("Sessionless HTTP request with authentication; this is expensive.")
 
 		error := func() {
 			time.Sleep(time.Duration(rand.Intn(100)+100) * time.Millisecond)

cmd/syncthing/main.go

@@ -7,6 +7,7 @@
 package main
 
 import (
+	"bytes"
 	"crypto/tls"
 	"flag"
 	"fmt"
@@ -21,16 +22,17 @@ import (
 	"regexp"
 	"runtime"
 	"runtime/pprof"
+	"sort"
 	"strconv"
 	"strings"
 	"time"
 
-	"github.com/calmh/logger"
 	"github.com/syncthing/syncthing/lib/config"
 	"github.com/syncthing/syncthing/lib/connections"
 	"github.com/syncthing/syncthing/lib/db"
 	"github.com/syncthing/syncthing/lib/discover"
 	"github.com/syncthing/syncthing/lib/events"
+	"github.com/syncthing/syncthing/lib/logger"
 	"github.com/syncthing/syncthing/lib/model"
 	"github.com/syncthing/syncthing/lib/osutil"
 	"github.com/syncthing/syncthing/lib/protocol"
@@ -71,6 +73,9 @@ const (
 	tlsDefaultCommonName = "syncthing"
 	tlsRSABits           = 3072
 	pingEventInterval    = time.Minute
+	maxSystemErrors      = 5
+	initialSystemLog     = 10
+	maxSystemLog         = 250
 )
 
 // The discovery results are sorted by their source priority.
@@ -80,8 +85,6 @@ const (
 	globalDiscoveryPriority
 )
 
-var l = logger.DefaultLogger
-
 func init() {
 	if Version != "unknown-dev" {
 		// If not a generic dev build, version string should come from git describe
@@ -148,25 +151,11 @@ Development Settings
 The following environment variables modify syncthing's behavior in ways that
 are mostly useful for developers. Use with care.
 
- STGUIASSETS     Directory to load GUI assets from. Overrides compiled in assets.
+ STGUIASSETS     Directory to load GUI assets from. Overrides compiled in
+                 assets.
 
  STTRACE         A comma separated string of facilities to trace. The valid
-                 facility strings are:
-
-                 - "beacon"   (the beacon package)
-                 - "discover" (the discover package)
-                 - "events"   (the events package)
-                 - "files"    (the files package)
-                 - "http"     (the main package; HTTP requests)
-                 - "locks"    (the sync package; trace long held locks)
-                 - "net"      (the main package; connections & network messages)
-                 - "model"    (the model package)
-                 - "scanner"  (the scanner package)
-                 - "stats"    (the stats package)
-                 - "suture"   (the suture package; service management)
-                 - "upnp"     (the upnp package)
-                 - "xdr"      (the xdr package)
-                 - "all"      (all of the above)
+                 facility strings listed below.
 
  STPROFILER      Set to a listen address such as "127.0.0.1:9090" to start the
                  profiler with HTTP access.
@@ -189,7 +178,15 @@ are mostly useful for developers. Use with care.
 
  GOGC            Percentage of heap growth at which to trigger GC. Default is
                  100. Lower numbers keep peak memory usage down, at the price
-                 of CPU usage (ie. performance).`
+                 of CPU usage (ie. performance).
+
+
+Debugging Facilities
+--------------------
+
+The following are valid values for the STTRACE variable:
+
+%s`
 )
 
 // Command line and environment options
@@ -245,7 +242,8 @@ func main() {
 	flag.BoolVar(&verbose, "verbose", false, "Print verbose log output")
 	flag.BoolVar(&paused, "paused", false, "Start with all devices paused")
 
-	flag.Usage = usageFor(flag.CommandLine, usage, fmt.Sprintf(extraUsage, baseDirs["config"]))
+	longUsage := fmt.Sprintf(extraUsage, baseDirs["config"], debugFacilities())
+	flag.Usage = usageFor(flag.CommandLine, usage, longUsage)
 	flag.Parse()
 
 	if noConsole {
@@ -397,6 +395,28 @@ func main() {
 	}
 }
 
+func debugFacilities() string {
+	facilities := l.Facilities()
+
+	// Get a sorted list of names
+	var names []string
+	maxLen := 0
+	for name := range facilities {
+		names = append(names, name)
+		if len(name) > maxLen {
+			maxLen = len(name)
+		}
+	}
+	sort.Strings(names)
+
+	// Format the choices
+	b := new(bytes.Buffer)
+	for _, name := range names {
+		fmt.Fprintf(b, " %-*s - %s\n", maxLen, name, facilities[name])
+	}
+	return b.String()
+}
+
 func upgradeViaRest() error {
 	cfg, err := config.Load(locations[locConfigFile], protocol.LocalDeviceID)
 	if err != nil {
@@ -439,9 +459,7 @@ func syncthingMain() {
 	// We want any logging it does to go through our log system.
 	mainSvc := suture.New("main", suture.Spec{
 		Log: func(line string) {
-			if debugSuture {
-				l.Debugln(line)
-			}
+			l.Debugln(line)
 		},
 	})
 	mainSvc.ServeBackground()
@@ -458,6 +476,9 @@ func syncthingMain() {
 		mainSvc.Add(newVerboseSvc())
 	}
 
+	errors := logger.NewRecorder(l, logger.LevelWarn, maxSystemErrors, 0)
+	systemLog := logger.NewRecorder(l, logger.LevelDebug, maxSystemLog, initialSystemLog)
+
 	// Event subscription for the API; must start early to catch the early events.
 	apiSub := events.NewBufferedSubscription(events.Default.Subscribe(events.AllEvents), 1000)
 
@@ -733,7 +754,7 @@ func syncthingMain() {
 
 	// GUI
 
-	setupGUI(mainSvc, cfg, m, apiSub, cachedDiscovery, relaySvc)
+	setupGUI(mainSvc, cfg, m, apiSub, cachedDiscovery, relaySvc, errors, systemLog)
 
 	// Start connection management
 
@@ -883,7 +904,7 @@ func startAuditing(mainSvc *suture.Supervisor) {
 	l.Infoln("Audit log in", auditFile)
 }
 
-func setupGUI(mainSvc *suture.Supervisor, cfg *config.Wrapper, m *model.Model, apiSub *events.BufferedSubscription, discoverer *discover.CachingMux, relaySvc *relay.Svc) {
+func setupGUI(mainSvc *suture.Supervisor, cfg *config.Wrapper, m *model.Model, apiSub *events.BufferedSubscription, discoverer *discover.CachingMux, relaySvc *relay.Svc, errors, systemLog *logger.Recorder) {
 	guiCfg := cfg.GUI()
 
 	if !guiCfg.Enabled {
@@ -918,7 +939,7 @@ func setupGUI(mainSvc *suture.Supervisor, cfg *config.Wrapper, m *model.Model, a
 		urlShow := fmt.Sprintf("%s://%s/", proto, net.JoinHostPort(hostShow, strconv.Itoa(addr.Port)))
 		l.Infoln("Starting web GUI on", urlShow)
 
-		api, err := newAPISvc(myID, cfg, guiAssets, m, apiSub, discoverer, relaySvc)
+		api, err := newAPISvc(myID, cfg, guiAssets, m, apiSub, discoverer, relaySvc, errors, systemLog)
 		if err != nil {
 			l.Fatalln("Cannot start GUI:", err)
 		}

cmd/syncthing/upnpsvc.go

@@ -98,9 +98,7 @@ func (s *upnpSvc) tryIGDs(igds []upnp.IGD, prevExtPort int) int {
 			l.Infof("New UPnP port mapping: external port %d to local port %d.", extPort, s.localPort)
 			events.Default.Log(events.ExternalPortMappingChanged, map[string]int{"port": extPort})
 		}
-		if debugNet {
-			l.Debugf("Created/updated UPnP port mapping for external port %d on device %s.", extPort, igd.FriendlyIdentifier())
-		}
+		l.Debugf("Created/updated UPnP port mapping for external port %d on device %s.", extPort, igd.FriendlyIdentifier())
 		return extPort
 	}