logging and fixes

app/application.go

@@ -4,19 +4,26 @@ import (
 	"fmt"
 	"os"
 	"os/signal"
+	"path"
 	"sync"
 	"syscall"
 	"time"
 
 	"fyne.io/systray"
+	"git.blackforestbytes.com/BlackForestBytes/goext/dataext"
 	"git.blackforestbytes.com/BlackForestBytes/goext/syncext"
 	"git.blackforestbytes.com/BlackForestBytes/goext/termext"
+	"git.blackforestbytes.com/BlackForestBytes/goext/timeext"
 	"mikescher.com/kpsync/assets"
 )
 
 type Application struct {
 	masterLock sync.Mutex
 
+	logLock sync.Mutex
+	logFile *os.File // file to write logs to, if set
+	logList []dataext.Triple[string, string, func(string) string]
+
 	config Config
 
 	trayReady       *syncext.AtomicBool
@@ -24,6 +31,8 @@ type Application struct {
 	syncLoopRunning *syncext.AtomicBool
 	keepassRunning  *syncext.AtomicBool
 
+	fileWatcherIgnore []dataext.Tuple[time.Time, string]
+
 	sigKPExitChan     chan bool  // keepass exited
 	sigManualStopChan chan bool  // manual stop
 	sigErrChan        chan error // fatal error
@@ -34,7 +43,7 @@ type Application struct {
 	dbFile    string
 	stateFile string
 
-	currSysTrayTooltop string
+	currSysTrayTooltip string
 
 	trayItemChecksum     *systray.MenuItem
 	trayItemETag         *systray.MenuItem
@@ -45,10 +54,13 @@ func NewApplication() *Application {
 
 	app := &Application{
 		masterLock:          sync.Mutex{},
+		logLock:             sync.Mutex{},
+		logList:             make([]dataext.Triple[string, string, func(string) string], 0, 1024),
 		uploadRunning:       syncext.NewAtomicBool(false),
 		trayReady:           syncext.NewAtomicBool(false),
 		syncLoopRunning:     syncext.NewAtomicBool(false),
 		keepassRunning:      syncext.NewAtomicBool(false),
+		fileWatcherIgnore:   make([]dataext.Tuple[time.Time, string], 0, 128),
 		sigKPExitChan:       make(chan bool, 128),
 		sigManualStopChan:   make(chan bool, 128),
 		sigErrChan:          make(chan error, 128),
@@ -56,7 +68,9 @@ func NewApplication() *Application {
 		sigTermKeepassChan:  make(chan bool, 128),
 	}
 
-	app.LogInfo("Starting kpsync...")
+	app.LogInfo(fmt.Sprintf("Starting kpsync {%s} ...", time.Now().In(timeext.TimezoneBerlin).Format(time.RFC3339)))
+	app.LogLine()
+
 	app.LogDebug(fmt.Sprintf("SupportsColors := %v", termext.SupportsColors()))
 	app.LogLine()
 
@@ -65,6 +79,7 @@ func NewApplication() *Application {
 
 func (app *Application) Run() {
 	var configPath string
+	var err error
 
 	app.config, configPath = app.loadConfig()
 
@@ -78,6 +93,17 @@ func (app *Application) Run() {
 	app.LogDebug(fmt.Sprintf("ForceColors   := %v", app.config.ForceColors))
 	app.LogLine()
 
+	app.logFile, err = os.OpenFile(path.Join(app.config.WorkDir, "kpsync.log"), os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0644)
+	if err != nil {
+		app.LogFatalErr("Failed to open log file", err)
+	}
+	defer func() {
+		if err := app.logFile.Close(); err != nil {
+			app.fallbackLog("Failed to close log file: " + err.Error())
+		}
+	}()
+	app.writeOutStartupLogs()
+
 	go func() { app.initTray() }()
 
 	go func() {
@@ -106,7 +132,7 @@ func (app *Application) Run() {
 
 			app.setTrayStateDirect("Sleeping...", assets.IconDefault)
 
-			err = app.runSyncLoop()
+			err = app.runSyncWatcher()
 			if err != nil {
 				app.sigErrChan <- err
 				return

app/logger.go

@@ -3,6 +3,7 @@ package app
 import (
 	"strings"
 
+	"git.blackforestbytes.com/BlackForestBytes/goext/dataext"
 	"git.blackforestbytes.com/BlackForestBytes/goext/exerr"
 	"git.blackforestbytes.com/BlackForestBytes/goext/langext"
 	"git.blackforestbytes.com/BlackForestBytes/goext/termext"
@@ -20,11 +21,11 @@ func (app *Application) LogFatal(msg string) {
 func (app *Application) LogFatalErr(msg string, err error) {
 	if err != nil {
 		app.logInternal("[F] ", msg+"\n"+err.Error()+"\n"+exerr.FromError(err).FormatLog(exerr.LogPrintOverview), termext.Red)
-		panic(0)
 	} else {
 		app.logInternal("[F] ", msg, termext.Red)
-		panic(0)
 	}
+
+	panic(0)
 }
 
 func (app *Application) LogError(msg string, err error) {
@@ -48,6 +49,9 @@ func (app *Application) LogDebug(msg string) {
 }
 
 func (app *Application) logInternal(pf string, msg string, c func(_ string) string) {
+	app.logLock.Lock()
+	defer app.logLock.Unlock()
+
 	if !termext.SupportsColors() && !app.config.ForceColors {
 		c = func(s string) string { return s }
 	}
@@ -55,12 +59,74 @@ func (app *Application) logInternal(pf string, msg string, c func(_ string) stri
 	for i, s := range strings.Split(msg, "\n") {
 		if i == 0 {
 			println(c(pf + s))
+			app.logList = append(app.logList, dataext.NewTriple(strings.TrimSpace(pf), s, c))
+			if app.logFile != nil {
+				_, err := app.logFile.WriteString(pf + s + "\n")
+				if err != nil {
+					app.fallbackLog("[!] Failed to write logfile: " + err.Error())
+				}
+			}
 		} else {
 			println(c(langext.StrRepeat(" ", len(pf)) + s))
+			app.logList = append(app.logList, dataext.NewTriple(strings.TrimSpace(pf), s, c))
+			if app.logFile != nil {
+				_, err := app.logFile.WriteString(langext.StrRepeat(" ", len(pf)) + s + "\n")
+				if err != nil {
+					app.fallbackLog("[!] Failed to write logfile: " + err.Error())
+				}
+			}
+		}
+	}
+
+	if app.logFile != nil {
+		err := app.logFile.Sync()
+		if err != nil {
+			app.fallbackLog("[!] Failed to flush logfile: " + err.Error())
 		}
 	}
 }
 
 func (app *Application) LogLine() {
+	app.logLock.Lock()
+	defer app.logLock.Unlock()
+
 	println()
+
+	if app.logFile != nil {
+		_, err := app.logFile.WriteString("\n")
+		if err != nil {
+			app.fallbackLog("[!] Failed to write logfile: " + err.Error())
+		}
+		err = app.logFile.Sync()
+		if err != nil {
+			app.fallbackLog("[!] Failed to flush logfile: " + err.Error())
+		}
+	}
+
+	app.logList = append(app.logList, dataext.NewTriple("", "", func(v string) string { return v }))
+}
+
+func (app *Application) fallbackLog(s string) {
+	if termext.SupportsColors() || app.config.ForceColors {
+		s = termext.Red(s)
+	}
+
+	println(s)
+}
+
+func (app *Application) writeOutStartupLogs() {
+	app.logLock.Lock()
+	defer app.logLock.Unlock()
+
+	for _, v := range app.logList {
+		_, err := app.logFile.WriteString(v.V1 + " " + v.V2 + "\n")
+		if err != nil {
+			app.fallbackLog("[!] Failed to write logfile: " + err.Error())
+		}
+	}
+
+	err := app.logFile.Sync()
+	if err != nil {
+		app.fallbackLog("[!] Failed to flush logfile: " + err.Error())
+	}
 }

app/notifications.go

@@ -67,6 +67,8 @@ func (app *Application) showChoiceNotification(msg string, body string, options
 
 	bldr := cmdext.
 		Runner("notify-send").
+		Arg("--urgency=critical").
+		Arg("--expire-time=0").
 		Arg("--wait").
 		Arg("--app-name=kpsync")
 

app/sync.go

@@ -12,7 +12,6 @@ import (
 	"git.blackforestbytes.com/BlackForestBytes/goext/exerr"
 	"git.blackforestbytes.com/BlackForestBytes/goext/langext"
 	"git.blackforestbytes.com/BlackForestBytes/goext/timeext"
-	"github.com/fsnotify/fsnotify"
 	"mikescher.com/kpsync/assets"
 )
 
@@ -49,7 +48,7 @@ func (app *Application) initSync() (InitSyncResponse, error) {
 		if err != nil {
 			app.LogError("Failed to calculate local database checksum", err)
 		} else if localCS == state.Checksum {
-			remoteETag, remoteLM, err := app.getRemoteETag()
+			remoteETag, remoteLM, err := app.getRemoteState()
 			if err != nil {
 				app.LogError("Failed to get remote ETag", err)
 			} else if remoteETag == state.ETag {
@@ -196,47 +195,6 @@ func (app *Application) runKeepass(fallback bool) {
 
 }
 
-func (app *Application) runSyncLoop() error {
-	watcher, err := fsnotify.NewWatcher()
-	if err != nil {
-		return exerr.Wrap(err, "failed to init file-watcher").Build()
-	}
-	defer func() { _ = watcher.Close() }()
-
-	err = watcher.Add(app.config.WorkDir)
-	if err != nil {
-		return exerr.Wrap(err, "").Build()
-	}
-
-	for {
-		select {
-		case <-app.sigSyncLoopStopChan:
-			app.LogInfo("Stopping sync loop (received signal)")
-			return nil
-
-		case event := <-watcher.Events:
-			app.LogDebug(fmt.Sprintf("Received inotify event: [%s] %s", event.Op.String(), event.Name))
-
-			if !event.Has(fsnotify.Write) && !event.Has(fsnotify.Create) {
-				app.LogDebug("Ignoring event - not a write|create event")
-				app.LogLine()
-				continue
-			}
-
-			if event.Name != app.dbFile {
-				app.LogDebug(fmt.Sprintf("Ignoring event - not the database file (%s)", app.dbFile))
-				app.LogLine()
-				continue
-			}
-
-			app.onDBFileChanged()
-
-		case err := <-watcher.Errors:
-			app.LogError("Filewatcher reported an error", err)
-		}
-	}
-}
-
 func (app *Application) onDBFileChanged() {
 	app.masterLock.Lock()
 	app.uploadRunning.Wait(false)
@@ -396,6 +354,11 @@ func (app *Application) runFinalSync() {
 
 	app.LogInfo("Starting final sync...")
 
+	remoteETag, _, err := app.getRemoteState()
+	if err != nil {
+		app.LogError("Failed to get remote ETag", err)
+	}
+
 	state := app.readState()
 	localCS, err := app.calcLocalChecksum()
 	if err != nil {
@@ -404,12 +367,56 @@ func (app *Application) runFinalSync() {
 		return
 	}
 
-	if state != nil && localCS == state.Checksum {
+	if state != nil && localCS == state.Checksum && remoteETag == state.ETag {
-		app.LogInfo("Local database still matches remote (via checksum) - no need to upload")
+		app.LogInfo("Local database still matches remote (via checksum+etag) - no need to upload")
 		app.LogInfo(fmt.Sprintf("Checksum (remote/cached) := %s", state.Checksum))
 		app.LogInfo(fmt.Sprintf("Checksum (local)         := %s", localCS))
+		app.LogDebug(fmt.Sprintf("ETag (local)            := %s", state.ETag))
+		app.LogDebug(fmt.Sprintf("ETag (remote)           := %s", remoteETag))
 		return
 	}
 
 	app.doDBUpload(state, fin1, false)
 }
+
+func (app *Application) runExplicitSync(force bool) {
+	app.masterLock.Lock()
+	app.uploadRunning.Wait(false)
+	app.uploadRunning.Set(true)
+	app.masterLock.Unlock()
+
+	defer app.uploadRunning.Set(false)
+
+	state := app.readState()
+
+	if !force {
+
+		remoteETag, _, err := app.getRemoteState()
+		if err != nil {
+			app.LogError("Failed to get remote ETag", err)
+			app.showErrorNotification("KeePassSync: Error", "Failed to get status from remote")
+			return
+		}
+
+		localCS, err := app.calcLocalChecksum()
+		if err != nil {
+			app.LogError("Failed to calculate local database checksum", err)
+			app.showErrorNotification("KeePassSync: Error", "Failed to calculate local database checksum")
+			return
+		}
+
+		if state != nil && localCS == state.Checksum {
+			app.LogInfo("Local database still matches remote (via checksum+etag) - no need to upload")
+			app.LogInfo(fmt.Sprintf("Checksum (remote/cached) := %s", state.Checksum))
+			app.LogInfo(fmt.Sprintf("Checksum (local)         := %s", localCS))
+			app.LogDebug(fmt.Sprintf("ETag (local)            := %s", state.ETag))
+			app.LogDebug(fmt.Sprintf("ETag (remote)           := %s", remoteETag))
+
+			app.showErrorNotification("KeePassSync", "No sync necessary - file is up-to-date with remote")
+			return
+		}
+
+	}
+
+	app.doDBUpload(state, func() {}, true)
+}

app/tray.go

@@ -16,8 +16,8 @@ func (app *Application) initTray() {
 
 		systray.SetIcon(assets.IconInit)
 		systray.SetTitle("KeepassXC Sync")
-		app.currSysTrayTooltop = "Initializing..."
+		app.currSysTrayTooltip = "Initializing..."
-		systray.SetTooltip(app.currSysTrayTooltop)
+		systray.SetTooltip(app.currSysTrayTooltip)
 
 		miSync := systray.AddMenuItem("Sync Now (checked)", "")
 		miSyncForce := systray.AddMenuItem("Sync Now (forced)", "")
@@ -37,10 +37,10 @@ func (app *Application) initTray() {
 				select {
 				case <-miSync.ClickedCh:
 					app.LogDebug("SysTray: [Sync Now (checked)] clicked")
-					//TODO
+					go func() { app.runExplicitSync(false) }()
 				case <-miSyncForce.ClickedCh:
 					app.LogDebug("SysTray: [Sync Now (forced)] clicked")
-					//TODO
+					go func() { app.runExplicitSync(true) }()
 				case <-miShowLog.ClickedCh:
 					app.LogDebug("SysTray: [Show Log] clicked")
 					//TODO
@@ -94,8 +94,8 @@ func (app *Application) setTrayState(txt string, icon []byte) func() {
 		}
 
 		systray.SetIcon(assets.IconDefault)
-		app.currSysTrayTooltop = "Sleeping..."
+		app.currSysTrayTooltip = "Sleeping..."
-		systray.SetTooltip(app.currSysTrayTooltop)
+		systray.SetTooltip(app.currSysTrayTooltip)
 
 		finDone = true
 	}
@@ -124,6 +124,6 @@ func (app *Application) setTrayTooltip(txt string) {
 	defer app.masterLock.Unlock()
 
 	systray.SetTooltip(txt)
-	app.currSysTrayTooltop = txt
+	app.currSysTrayTooltip = txt
-	systray.SetTooltip(app.currSysTrayTooltop)
+	systray.SetTooltip(app.currSysTrayTooltip)
 }

app/watcher.go

@@ -0,0 +1,70 @@
+package app
+
+import (
+	"fmt"
+	"time"
+
+	"git.blackforestbytes.com/BlackForestBytes/goext/exerr"
+	"github.com/fsnotify/fsnotify"
+)
+
+func (app *Application) runSyncWatcher() error {
+	watcher, err := fsnotify.NewWatcher()
+	if err != nil {
+		return exerr.Wrap(err, "failed to init file-watcher").Build()
+	}
+	defer func() { _ = watcher.Close() }()
+
+	err = watcher.Add(app.config.WorkDir)
+	if err != nil {
+		return exerr.Wrap(err, "").Build()
+	}
+
+	for {
+		select {
+		case <-app.sigSyncLoopStopChan:
+			app.LogInfo("Stopping sync loop (received signal)")
+			return nil
+
+		case event := <-watcher.Events:
+			if event.Name != app.dbFile {
+				continue // no log!! otherwise we end in an endless log-loop
+			}
+			if !event.Has(fsnotify.Write) && !event.Has(fsnotify.Create) {
+				continue // no log!! otherwise we end in an endless log-loop
+			}
+
+			app.LogDebug(fmt.Sprintf("Received inotify event: [%s] %s", event.Op.String(), event.Name))
+
+			localCS, err := app.calcLocalChecksum()
+			if err != nil {
+				app.LogError("Failed to calculate local database checksum", err)
+				app.showErrorNotification("KeePassSync: Error", "Failed to calculate checksum")
+				continue
+			}
+
+			ignoreFN := func() bool {
+				app.masterLock.Lock()
+				defer app.masterLock.Unlock()
+
+				for _, ign := range app.fileWatcherIgnore {
+					if ign.V2 == localCS && time.Since(ign.V1) < 10*time.Second {
+						return true
+					}
+				}
+
+				return false
+			}
+
+			if ignoreFN() {
+				app.LogDebug("Ignoring file-change - event is explicitly ignored")
+				continue
+			}
+
+			app.onDBFileChanged()
+
+		case err := <-watcher.Errors:
+			app.LogError("Filewatcher reported an error", err)
+		}
+	}
+}

app/webdav.go

@@ -10,6 +10,7 @@ import (
 	"time"
 
 	"git.blackforestbytes.com/BlackForestBytes/goext/cryptext"
+	"git.blackforestbytes.com/BlackForestBytes/goext/dataext"
 	"git.blackforestbytes.com/BlackForestBytes/goext/exerr"
 	"git.blackforestbytes.com/BlackForestBytes/goext/timeext"
 )
@@ -18,7 +19,7 @@ var ETagConflictError = errors.New("ETag conflict")
 
 func (app *Application) downloadDatabase() (string, time.Time, string, int64, error) {
 
-	prevTT := app.currSysTrayTooltop
+	prevTT := app.currSysTrayTooltip
 	defer app.setTrayTooltip(prevTT)
 
 	client := http.Client{Timeout: 90 * time.Second}
@@ -67,6 +68,10 @@ func (app *Application) downloadDatabase() (string, time.Time, string, int64, er
 
 	sz := int64(len(bin))
 
+	app.masterLock.Lock()
+	app.fileWatcherIgnore = append(app.fileWatcherIgnore, dataext.NewTuple(time.Now(), sha))
+	app.masterLock.Unlock()
+
 	err = os.WriteFile(app.dbFile, bin, 0644)
 	if err != nil {
 		return "", time.Time{}, "", 0, exerr.Wrap(err, "Failed to write database file").Build()
@@ -75,7 +80,7 @@ func (app *Application) downloadDatabase() (string, time.Time, string, int64, er
 	return etag, lm, sha, sz, nil
 }
 
-func (app *Application) getRemoteETag() (string, time.Time, error) {
+func (app *Application) getRemoteState() (string, time.Time, error) {
 	client := http.Client{Timeout: 90 * time.Second}
 
 	req, err := http.NewRequest("HEAD", app.config.WebDAVURL, nil)
@@ -109,7 +114,7 @@ func (app *Application) getRemoteETag() (string, time.Time, error) {
 
 func (app *Application) uploadDatabase(etagIfMatch *string) (string, time.Time, string, int64, error) {
 
-	prevTT := app.currSysTrayTooltop
+	prevTT := app.currSysTrayTooltip
 	defer app.setTrayTooltip(prevTT)
 
 	client := http.Client{Timeout: 90 * time.Second}