From 83d6aa10cb54c67de9415eb8bdb33c141d830d60 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mike=20Schw=C3=B6rer?= Date: Wed, 20 Aug 2025 13:29:12 +0200 Subject: [PATCH] logging and fixes --- app/application.go | 32 +++++++++++++-- app/logger.go | 70 +++++++++++++++++++++++++++++++- app/notifications.go | 2 + app/sync.go | 97 ++++++++++++++++++++++++-------------------- app/tray.go | 16 ++++---- app/watcher.go | 70 ++++++++++++++++++++++++++++++++ app/webdav.go | 13 ++++-- 7 files changed, 238 insertions(+), 62 deletions(-) create mode 100644 app/watcher.go diff --git a/app/application.go b/app/application.go index b1d4e0e..6c84d41 100644 --- a/app/application.go +++ b/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 diff --git a/app/logger.go b/app/logger.go index ce463b1..994a34e 100644 --- a/app/logger.go +++ b/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()) + } } diff --git a/app/notifications.go b/app/notifications.go index 9b68f6b..9341c09 100644 --- a/app/notifications.go +++ b/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") diff --git a/app/sync.go b/app/sync.go index 20f07f3..bf6bb5d 100644 --- a/app/sync.go +++ b/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 { - app.LogInfo("Local database still matches remote (via checksum) - no need to upload") + if state != nil && localCS == state.Checksum && remoteETag == state.ETag { + 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) +} diff --git a/app/tray.go b/app/tray.go index 8856947..2d55855 100644 --- a/app/tray.go +++ b/app/tray.go @@ -16,8 +16,8 @@ func (app *Application) initTray() { systray.SetIcon(assets.IconInit) systray.SetTitle("KeepassXC Sync") - app.currSysTrayTooltop = "Initializing..." - systray.SetTooltip(app.currSysTrayTooltop) + app.currSysTrayTooltip = "Initializing..." + 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..." - systray.SetTooltip(app.currSysTrayTooltop) + app.currSysTrayTooltip = "Sleeping..." + 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 - systray.SetTooltip(app.currSysTrayTooltop) + app.currSysTrayTooltip = txt + systray.SetTooltip(app.currSysTrayTooltip) } diff --git a/app/watcher.go b/app/watcher.go new file mode 100644 index 0000000..6fdf340 --- /dev/null +++ b/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) + } + } +} diff --git a/app/webdav.go b/app/webdav.go index f37ffa0..2402a73 100644 --- a/app/webdav.go +++ b/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} @@ -176,7 +181,7 @@ func (app *Application) uploadDatabase(etagIfMatch *string) (string, time.Time, func (app *Application) parseHeader(resp *http.Response) (string, time.Time, error) { var err error - + etag := resp.Header.Get("ETag") if etag == "" { return "", time.Time{}, exerr.New(exerr.TypeInternal, "ETag header is missing").Build()