Add audit log feature

cmd/syncthing/audit.go

@@ -0,0 +1,69 @@
+// 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 (
+	"encoding/json"
+	"io"
+
+	"github.com/syncthing/syncthing/internal/events"
+)
+
+// The auditSvc subscribes to events and writes these in JSON format, one
+// event per line, to the specified writer.
+type auditSvc struct {
+	w       io.Writer     // audit destination
+	stop    chan struct{} // signals time to stop
+	started chan struct{} // signals startup complete
+	stopped chan struct{} // signals stop complete
+}
+
+func newAuditSvc(w io.Writer) *auditSvc {
+	return &auditSvc{
+		w:       w,
+		stop:    make(chan struct{}),
+		started: make(chan struct{}),
+		stopped: make(chan struct{}),
+	}
+}
+
+// Serve runs the audit service.
+func (s *auditSvc) Serve() {
+	defer close(s.stopped)
+	sub := events.Default.Subscribe(events.AllEvents)
+	defer events.Default.Unsubscribe(sub)
+	enc := json.NewEncoder(s.w)
+
+	// We're ready to start processing events.
+	close(s.started)
+
+	for {
+		select {
+		case ev := <-sub.C():
+			enc.Encode(ev)
+		case <-s.stop:
+			return
+		}
+	}
+}
+
+// Stop stops the audit service.
+func (s *auditSvc) Stop() {
+	close(s.stop)
+}
+
+// WaitForStart returns once the audit service is ready to receive events, or
+// immediately if it's already running.
+func (s *auditSvc) WaitForStart() {
+	<-s.started
+}
+
+// WaitForStop returns once the audit service has stopped.
+// (Needed by the tests.)
+func (s *auditSvc) WaitForStop() {
+	<-s.stopped
+}

cmd/syncthing/auditsvc_test.go

@@ -0,0 +1,54 @@
+// 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 (
+	"bytes"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/syncthing/syncthing/internal/events"
+)
+
+func TestAuditService(t *testing.T) {
+	buf := new(bytes.Buffer)
+	svc := newAuditSvc(buf)
+
+	// Event sent before start, will not be logged
+	events.Default.Log(events.Ping, "the first event")
+
+	go svc.Serve()
+	svc.WaitForStart()
+
+	// Event that should end up in the audit log
+	events.Default.Log(events.Ping, "the second event")
+
+	// We need to give the events time to arrive, since the channels are buffered etc.
+	time.Sleep(10 * time.Millisecond)
+
+	svc.Stop()
+	svc.WaitForStop()
+
+	// This event should not be logged, since we have stopped.
+	events.Default.Log(events.Ping, "the third event")
+
+	result := string(buf.Bytes())
+	t.Log(result)
+
+	if strings.Contains(result, "first event") {
+		t.Error("Unexpected first event")
+	}
+
+	if !strings.Contains(result, "second event") {
+		t.Error("Missing second event")
+	}
+
+	if strings.Contains(result, "third event") {
+		t.Error("Missing third event")
+	}
+}

cmd/syncthing/locations.go

@@ -11,6 +11,7 @@ import (
 	"path/filepath"
 	"runtime"
 	"strings"
+	"time"
 
 	"github.com/syncthing/syncthing/internal/osutil"
 )
@@ -29,6 +30,7 @@ const (
 	locLogFile                    = "logFile"
 	locCsrfTokens                 = "csrfTokens"
 	locPanicLog                   = "panicLog"
+	locAuditLog                   = "auditLog"
 	locDefFolder                  = "defFolder"
 )
 
@@ -48,7 +50,8 @@ var locations = map[locationEnum]string{
 	locDatabase:      "${config}/index-v0.11.0.db",
 	locLogFile:       "${config}/syncthing.log", // -logfile on Windows
 	locCsrfTokens:    "${config}/csrftokens.txt",
-	locPanicLog:      "${config}/panic-20060102-150405.log", // passed through time.Format()
+	locPanicLog:      "${config}/panic-${timestamp}.log",
+	locAuditLog:      "${config}/audit-${timestamp}.log",
 	locDefFolder:     "${home}/Sync",
 }
 
@@ -107,3 +110,14 @@ func homeDir() string {
 	}
 	return home
 }
+
+func timestampedLoc(key locationEnum) string {
+	// We take the roundtrip via "${timestamp}" instead of passing the path
+	// directly through time.Format() to avoid issues when the path we are
+	// expanding contains numbers; otherwise for example
+	// /home/user2006/.../panic-20060102-150405.log would get both instances of
+	// 2006 replaced by 2015...
+	tpl := locations[key]
+	now := time.Now().Format("20060102-150405")
+	return strings.Replace(tpl, "${timestamp}", now, -1)
+}

cmd/syncthing/main.go

@@ -196,6 +196,7 @@ var (
 	noConsole         bool
 	generateDir       string
 	logFile           string
+	auditEnabled      bool
 	noRestart         = os.Getenv("STNORESTART") != ""
 	noUpgrade         = os.Getenv("STNOUPGRADE") != ""
 	guiAddress        = os.Getenv("STGUIADDRESS") // legacy
@@ -232,6 +233,7 @@ func main() {
 	flag.BoolVar(&doUpgradeCheck, "upgrade-check", false, "Check for available upgrade")
 	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.Usage = usageFor(flag.CommandLine, usage, fmt.Sprintf(extraUsage, baseDirs["config"]))
 	flag.Parse()
@@ -384,6 +386,14 @@ func syncthingMain() {
 	})
 	mainSvc.ServeBackground()
 
+	// Set a log prefix similar to the ID we will have later on, or early log
+	// lines look ugly.
+	l.SetPrefix("[start] ")
+
+	if auditEnabled {
+		startAuditing(mainSvc)
+	}
+
 	if len(os.Getenv("GOMAXPROCS")) == 0 {
 		runtime.GOMAXPROCS(runtime.NumCPU())
 	}
@@ -654,6 +664,23 @@ func syncthingMain() {
 	os.Exit(code)
 }
 
+func startAuditing(mainSvc *suture.Supervisor) {
+	auditFile := timestampedLoc(locAuditLog)
+	fd, err := os.OpenFile(auditFile, os.O_WRONLY|os.O_CREATE|os.O_EXCL, 0600)
+	if err != nil {
+		l.Fatalln("Audit:", err)
+	}
+
+	auditSvc := newAuditSvc(fd)
+	mainSvc.Add(auditSvc)
+
+	// We wait for the audit service to fully start before we return, to
+	// ensure we capture all events from the start.
+	auditSvc.WaitForStart()
+
+	l.Infoln("Audit log in", auditFile)
+}
+
 func setupGUI(cfg *config.Wrapper, m *model.Model) {
 	opts := cfg.Options()
 	guiCfg := overrideGUIConfig(cfg.GUI(), guiAddress, guiAuthentication, guiAPIKey)
@@ -1023,6 +1050,7 @@ func autoUpgrade() {
 func cleanConfigDirectory() {
 	patterns := map[string]time.Duration{
 		"panic-*.log":    7 * 24 * time.Hour,  // keep panic logs for a week
+		"audit-*.log":    7 * 24 * time.Hour,  // keep audit logs for a week
 		"index":          14 * 24 * time.Hour, // keep old index format for two weeks
 		"config.xml.v*":  30 * 24 * time.Hour, // old config versions for a month
 		"*.idx.gz":       30 * 24 * time.Hour, // these should for sure no longer exist

cmd/syncthing/monitor.go

@@ -163,7 +163,7 @@ func copyStderr(stderr io.ReadCloser, dst io.Writer) {
 			dst.Write([]byte(line))
 
 			if strings.HasPrefix(line, "panic:") || strings.HasPrefix(line, "fatal error:") {
-				panicFd, err = os.Create(time.Now().Format(locations[locPanicLog]))
+				panicFd, err = os.Create(timestampedLoc(locPanicLog))
 				if err != nil {
 					l.Warnln("Create panic log:", err)
 					continue

test/.gitignore

@@ -17,3 +17,6 @@ s4d
 http
 h*/index*
 *.syncthing-reset*
+panic-*.log
+audit-*.log
+h*/config.xml.v*