From 9ed101830b72860d609aa2894f2f50bc25cd6412 Mon Sep 17 00:00:00 2001 From: intergrav Date: Tue, 07 Jul 2026 14:19:06 +0000 Subject: [PATCH] fix: various improvements to scheduling and logging mainly improving consistency between the daemon/cli and gui also improved some variable and function names to be cleaner / fit better with what their actual purpose is --- cmd/restray/cli.go | 142 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++--------------------------------- cmd/restray/config.go | 12 +++++++++++- cmd/restray/operations.go | 153 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---------------------------------------- cmd/restray/tray.go | 65 +++++++++++++++++++++++++++++++++++------------------------------ 4 file(s) changed, 268 insertion(s)(+), 104 deletion(s)(-) diff --git a/cmd/restray/cli.go b/cmd/restray/cli.go --- a/cmd/restray/cli.go +++ b/cmd/restray/cli.go @@ -1,15 +1,18 @@ package main import ( + "bufio" "context" "errors" "fmt" + "io" "log" "os" "os/exec" "os/signal" "runtime" "strings" + "sync" "sync/atomic" "syscall" @@ -109,6 +112,59 @@ } return nil } +func cliRunResticRetryLock(prof Profile, args []string) error { + err := cliRunRestic(prof, args...) + if err != nil && exitCode(err) == 11 && retryLockEnabled(prof) { + log.Printf("[%s] locked, running unlock and retrying", prof.displayName()) + _ = cliRunRestic(prof, "unlock") + err = cliRunRestic(prof, args...) + } + return err +} + +func cliRunCmdLogged(prof Profile, cmd *exec.Cmd) error { + stdoutPipe, _ := cmd.StdoutPipe() + stderrPipe, _ := cmd.StderrPipe() + if err := cmd.Start(); err != nil { + return cli.Exit("", exitCode(err)) + } + var wg sync.WaitGroup + for _, pipe := range []io.Reader{stdoutPipe, stderrPipe} { + wg.Add(1) + go func(pipe io.Reader) { + defer wg.Done() + scanner := bufio.NewScanner(pipe) + for scanner.Scan() { + logPrefixedLine(prof.displayName(), scanner.Text()) + } + }(pipe) + } + err := cmd.Wait() + wg.Wait() + if err != nil { + return cli.Exit("", exitCode(err)) + } + return nil +} + +func cliRunResticLogged(prof Profile, args ...string) error { + p, _ := findRestic() + if p == "" { + return cli.Exit("error: restic not found", 1) + } + return cliRunCmdLogged(prof, resticCmd(prof, args...)) +} + +func cliRunResticRetryLockLogged(prof Profile, args []string) error { + err := cliRunResticLogged(prof, args...) + if err != nil && exitCode(err) == 11 && retryLockEnabled(prof) { + log.Printf("[%s] locked, running unlock and retrying", prof.displayName()) + _ = cliRunResticLogged(prof, "unlock") + err = cliRunResticLogged(prof, args...) + } + return err +} + func cliRunHook(hook string, prof Profile, extraEnv ...string) error { if hook == "" { return cli.Exit("error: no hook configured", 1) @@ -122,16 +178,23 @@ } return nil } +func cliRunHookLogged(hook string, prof Profile, extraEnv ...string) error { + if hook == "" { + return cli.Exit("error: no hook configured", 1) + } + return cliRunCmdLogged(prof, hookCmd(hook, prof, extraEnv...)) +} + func cliBackup(prof Profile, scheduled bool) error { - return cliRunRestic(prof, backupArgs(prof, scheduled)...) + return cliRunResticRetryLock(prof, backupArgs(prof, scheduled)) } func cliPrune(prof Profile) error { - return cliRunRestic(prof, forgetArgs(prof)...) + return cliRunResticRetryLock(prof, addRetryLockArgs(prof, forgetArgs(prof))) } func cliCheck(prof Profile) error { - return cliRunRestic(prof, checkArgs(prof)...) + return cliRunResticRetryLock(prof, addRetryLockArgs(prof, checkArgs(prof))) } func cliUnlock(prof Profile) error { @@ -204,52 +267,58 @@ interrupted.Store(true) }() hookEnv := []string{ - "RESTRAY_OPERATIONS=" + strings.Join(scheduledOps(prof), ","), + "RESTRAY_OPERATIONS=" + strings.Join(scheduledOpNames(prof), ","), "RESTRAY_SCHEDULED=true", } if prof.PreHook != "" { log.Printf("[%s] running pre-hook", prof.displayName()) - if err := cliRunHook(prof.PreHook, prof, hookEnv...); err != nil { + if err := cliRunHookLogged(prof.PreHook, prof, hookEnv...); err != nil { return cli.Exit("error: pre-hook failed", 1) } } - failed := false - - if !interrupted.Load() && prof.Schedule.BackupEnabled() { - log.Printf("[%s] running backup", prof.displayName()) - if err := cliBackup(prof, true); err != nil { - failed = true - } - } - - if !interrupted.Load() && prof.Schedule.Prune && len(prof.Prune.Args) > 0 { - log.Printf("[%s] running prune", prof.displayName()) - if err := cliPrune(prof); err != nil { - failed = true - } - } - - if !interrupted.Load() && prof.Schedule.Check { - log.Printf("[%s] running check", prof.displayName()) - if err := cliCheck(prof); err != nil { - failed = true - } - } + failed, failMsg := runScheduledOperations( + prof, + interrupted.Load, + func() (bool, string) { + log.Printf("[%s] running backup", prof.displayName()) + if err := cliRunResticRetryLockLogged(prof, backupArgs(prof, true)); err != nil { + return false, "backup failed" + } + return true, "" + }, + func() (bool, string) { + log.Printf("[%s] running prune", prof.displayName()) + if err := cliRunResticRetryLockLogged(prof, addRetryLockArgs(prof, forgetArgs(prof))); err != nil { + return false, "prune failed" + } + return true, "" + }, + func() (bool, string) { + log.Printf("[%s] running check", prof.displayName()) + if err := cliRunResticRetryLockLogged(prof, addRetryLockArgs(prof, checkArgs(prof))); err != nil { + return false, "check failed" + } + return true, "" + }, + ) if prof.PostHook != "" { signal.Reset(os.Interrupt, syscall.SIGTERM) log.Printf("[%s] running post-hook", prof.displayName()) postEnv := hookEnv if failed || interrupted.Load() { - errMsg := "operation failed" + errMsg := failMsg + if errMsg == "" { + errMsg = "operation failed" + } if interrupted.Load() { errMsg = "interrupted by user" } postEnv = append(postEnv, "RESTRAY_ERROR="+errMsg) } - if err := cliRunHook(prof.PostHook, prof, postEnv...); err != nil { + if err := cliRunHookLogged(prof.PostHook, prof, postEnv...); err != nil { return cli.Exit("error: post-hook failed", 1) } } @@ -267,6 +336,10 @@ if prof.Schedule.Cron == "" { continue } name := prof.displayName() + if errMsg := prof.scheduleError(); errMsg != "" { + log.Printf("[%s] skipping schedule: %s", name, errMsg) + continue + } _, err := sched.AddFunc(prof.Schedule.Cron, func() { current := loadConfig() prof, err := resolveProfileAt(current, idx, name) @@ -288,15 +361,18 @@ if r := recover(); r != nil { log.Printf("[%s] scheduled run panicked: %v", prof.displayName(), r) } }() - log.Printf("[%s] running scheduled job", prof.displayName()) - cliSchedule(prof) + log.Printf("[%s] starting scheduled run", prof.displayName()) + if err := cliSchedule(prof); err != nil { + log.Printf("[%s] scheduled run failed: %v", prof.displayName(), err) + } }) if err != nil { - return nil, fmt.Errorf("invalid cron expression %q for profile %q: %w", prof.Schedule.Cron, name, err) + log.Printf("[%s] skipping schedule: invalid cron expression %q: %v", name, prof.Schedule.Cron, err) + continue } } if len(sched.Entries()) == 0 { - return nil, errors.New("no profiles have a schedule configured") + return nil, errors.New("no profiles have a valid schedule configured") } return sched, nil } diff --git a/cmd/restray/config.go b/cmd/restray/config.go --- a/cmd/restray/config.go +++ b/cmd/restray/config.go @@ -117,7 +117,7 @@ } return env, nil } -func (prof Profile) configError() string { +func (prof Profile) scheduleError() string { vars, err := parseEnvFile(prof.EnvFile) if err != nil { return "Env file not found" @@ -127,6 +127,16 @@ return "RESTIC_REPOSITORY not set in env file" } if vars["RESTIC_PASSWORD"] == "" && vars["RESTIC_PASSWORD_FILE"] == "" && vars["RESTIC_PASSWORD_COMMAND"] == "" { return "No password set in env file" + } + if prof.Schedule.BackupEnabled() && len(prof.Backup.Paths) == 0 { + return "No paths configured" + } + return "" +} + +func (prof Profile) configError() string { + if err := prof.scheduleError(); err != "" { + return err } if len(prof.Backup.Paths) == 0 { return "No paths configured" diff --git a/cmd/restray/operations.go b/cmd/restray/operations.go --- a/cmd/restray/operations.go +++ b/cmd/restray/operations.go @@ -19,35 +19,55 @@ "github.com/dustin/go-humanize" "github.com/gen2brain/beeep" ) -type stderrLogger struct { +type lastLineLogger struct { mu sync.Mutex last string } -func (s *stderrLogger) lastLine() string { +func (s *lastLineLogger) lastLine() string { s.mu.Lock() defer s.mu.Unlock() return s.last } -func streamStderr(pipe io.Reader, mStatus prefixedMenuItem) *stderrLogger { - sl := &stderrLogger{} +func logPrefixedLine(name, line string) { + log.Printf("[%s] %s", name, line) +} + +func logPrefixedOutput(name, out string) { + for _, line := range strings.Split(strings.ReplaceAll(out, "\r\n", "\n"), "\n") { + if line != "" { + logPrefixedLine(name, line) + } + } +} + +func streamLogLines(pipe io.Reader, name string, onLine func(string)) *lastLineLogger { + sl := &lastLineLogger{} go func() { scanner := bufio.NewScanner(pipe) for scanner.Scan() { line := scanner.Text() - log.Print(line) + logPrefixedLine(name, line) sl.mu.Lock() sl.last = line sl.mu.Unlock() - if trimmed := strings.TrimSpace(line); trimmed != "" { - mStatus.SetTitle(trimmed) + if onLine != nil { + onLine(line) } } }() return sl } +func streamStderr(pipe io.Reader, prof Profile, mStatus prefixedMenuItem) *lastLineLogger { + return streamLogLines(pipe, prof.displayName(), func(line string) { + if trimmed := strings.TrimSpace(line); trimmed != "" { + mStatus.SetTitle(trimmed) + } + }) +} + func runResticOnce(idx profileIndex, prof Profile, mStatus prefixedMenuItem, args ...string) (string, error) { cmd := resticCmd(prof, args...) var stdout strings.Builder @@ -60,10 +80,10 @@ log.Printf("[%s] start failed: %v", prof.displayName(), err) return err.Error(), err } - sl := streamStderr(stderrPipe, mStatus) + sl := streamStderr(stderrPipe, prof, mStatus) err := cmd.Wait() if out := stdout.String(); out != "" { - log.Print(out) + logPrefixedOutput(prof.displayName(), out) } if err == nil { log.Printf("[%s] done: restic %s", prof.displayName(), args[0]) @@ -111,7 +131,7 @@ setProfileFailed(idx, err.Error()) return false, -1 } - sl := streamStderr(stderrPipe, mStatus) + sl := streamStderr(stderrPipe, prof, mStatus) scanner := bufio.NewScanner(stdoutPipe) for scanner.Scan() { @@ -126,7 +146,7 @@ TotalFiles uint64 `json:"total_files"` FilesDone uint64 `json:"files_done"` } if json.Unmarshal([]byte(line), &msg) != nil || msg.Type == "" { - log.Print(line) + logPrefixedLine(prof.displayName(), line) continue } if msg.Type == "status" { @@ -141,7 +161,7 @@ default: mStatus.SetTitle(fmt.Sprintf("Scanning: %d files", msg.FilesDone)) } } else { - log.Print(line) + logPrefixedLine(prof.displayName(), line) } } @@ -234,13 +254,16 @@ } cmd := hookCmd(hook, prof, extraEnv...) log.Printf("[%s] running hook: %s", prof.displayName(), hook) out, err := cmd.CombinedOutput() + if len(out) > 0 { + logPrefixedOutput(prof.displayName(), string(out)) + } if err != nil { - log.Printf("[%s] hook %q failed: %v: %s", prof.displayName(), hook, err, out) + log.Printf("[%s] hook %q failed: %v", prof.displayName(), hook, err) } return err } -func scheduledOps(prof Profile) []string { +func scheduledOpNames(prof Profile) []string { var ops []string if prof.Schedule.BackupEnabled() { ops = append(ops, "backup") @@ -254,6 +277,48 @@ } return ops } +func runScheduledOperations( + prof Profile, + interrupted func() bool, + runBackup func() (bool, string), + runPrune func() (bool, string), + runCheck func() (bool, string), +) (bool, string) { + isInterrupted := func() bool { + return interrupted != nil && interrupted() + } + + failed := false + failMsg := "" + skipRemaining := false + + if !isInterrupted() && prof.Schedule.BackupEnabled() { + if ok, msg := runBackup(); !ok { + failed = true + failMsg = msg + skipRemaining = true + } + } + if !isInterrupted() && !skipRemaining && prof.Schedule.Prune && len(prof.Prune.Args) > 0 { + if ok, msg := runPrune(); !ok { + failed = true + if failMsg == "" { + failMsg = msg + } + } + } + if !isInterrupted() && !skipRemaining && prof.Schedule.Check { + if ok, msg := runCheck(); !ok { + failed = true + if failMsg == "" { + failMsg = msg + } + } + } + + return failed, failMsg +} + func runScheduled(idx profileIndex, mStatus prefixedMenuItem, prof Profile, onDone func()) { if p, _ := findRestic(); p == "" { return @@ -266,7 +331,7 @@ defer onDone() defer releaseProfile(idx) hookEnv := []string{ - "RESTRAY_OPERATIONS=" + strings.Join(scheduledOps(prof), ","), + "RESTRAY_OPERATIONS=" + strings.Join(scheduledOpNames(prof), ","), "RESTRAY_SCHEDULED=true", } @@ -279,29 +344,33 @@ return } } - failed := false - skipRemaining := false - if prof.Schedule.BackupEnabled() { - mStatus.SetTitle("Backing up...") - if ok, _ := doBackup(idx, mStatus, prof, true); !ok { - failed = true - skipRemaining = true - } - } - if !skipRemaining && prof.Schedule.Prune && len(prof.Prune.Args) > 0 { - mStatus.SetTitle("Pruning repository...") - if msg, err := runRestic(idx, prof, mStatus, forgetArgs(prof)...); err != nil { - setProfileFailed(idx, msg) - failed = true - } - } - if !skipRemaining && prof.Schedule.Check { - mStatus.SetTitle("Checking repository...") - if msg, err := runRestic(idx, prof, mStatus, checkArgs(prof)...); err != nil { - setProfileFailed(idx, msg) - failed = true - } - } + failed, _ := runScheduledOperations( + prof, + nil, + func() (bool, string) { + mStatus.SetTitle("Backing up...") + if ok, _ := doBackup(idx, mStatus, prof, true); !ok { + return false, getProfileFailStatus(idx) + } + return true, "" + }, + func() (bool, string) { + mStatus.SetTitle("Pruning repository...") + if msg, err := runRestic(idx, prof, mStatus, forgetArgs(prof)...); err != nil { + setProfileFailed(idx, msg) + return false, msg + } + return true, "" + }, + func() (bool, string) { + mStatus.SetTitle("Checking repository...") + if msg, err := runRestic(idx, prof, mStatus, checkArgs(prof)...); err != nil { + setProfileFailed(idx, msg) + return false, msg + } + return true, "" + }, + ) if failed { notifyError("Schedule", getProfileFailStatus(idx)) @@ -322,11 +391,15 @@ } } } -func backupArgs(prof Profile, scheduled bool, extra ...string) []string { - args := append([]string{"backup"}, extra...) +func addRetryLockArgs(prof Profile, args []string) []string { if retryLockEnabled(prof) { args = append(args, "--retry-lock", prof.RetryLock) } + return args +} + +func backupArgs(prof Profile, scheduled bool, extra ...string) []string { + args := addRetryLockArgs(prof, append([]string{"backup"}, extra...)) args = append(args, prof.Backup.Args...) if scheduled { args = append(args, prof.Backup.ArgsScheduled...) diff --git a/cmd/restray/tray.go b/cmd/restray/tray.go --- a/cmd/restray/tray.go +++ b/cmd/restray/tray.go @@ -565,6 +565,7 @@ markActiveProfile(activeIdx, len(cfg.Profiles)) setProfileTitle(cfg, activeIdx) sched.Start() + setIconAnimated("busy") var wg sync.WaitGroup for i, prof := range cfg.Profiles { @@ -584,35 +585,39 @@ go func(i int, prof Profile) { defer wg.Done() ps := probeProfileState(cfg, i, prof) - if ps.errMsg == "" && prof.Schedule.Cron != "" { - name := prof.displayName() - eid, err := sched.AddFunc(prof.Schedule.Cron, func() { - current := loadConfig() - prof, err := resolveProfileAt(current, i, name) + if prof.Schedule.Cron != "" { + if errMsg := prof.scheduleError(); errMsg != "" { + log.Printf("[%s] skipping schedule: %s", prof.displayName(), errMsg) + } else { + name := prof.displayName() + eid, err := sched.AddFunc(prof.Schedule.Cron, func() { + current := loadConfig() + prof, err := resolveProfileAt(current, i, name) + if err != nil { + log.Printf("[%s] skipping scheduled run: %v", name, err) + return + } + if skipForBattery(prof) { + log.Printf("[%s] skipping scheduled run: on battery power", prof.displayName()) + return + } + go func() { + defer func() { + if r := recover(); r != nil { + log.Printf("[%s] scheduled run panicked: %v", prof.displayName(), r) + } + }() + runScheduled(i, statusItem(i), prof, func() { finishProfile(i) }) + }() + }) if err != nil { - log.Printf("[%s] skipping scheduled backup: %v", name, err) - return + log.Printf("[%s] invalid cron expression %q: %v", prof.displayName(), prof.Schedule.Cron, err) + ps.errMsg = "Invalid cron: " + prof.Schedule.Cron + } else { + profileMu.Lock() + profileEntryIDs[i] = append(profileEntryIDs[i], eid) + profileMu.Unlock() } - if skipForBattery(prof) { - log.Printf("[%s] skipping scheduled backup: on battery power", prof.displayName()) - return - } - go func() { - defer func() { - if r := recover(); r != nil { - log.Printf("[%s] scheduled run panicked: %v", prof.displayName(), r) - } - }() - runScheduled(i, statusItem(i), prof, func() { finishProfile(i) }) - }() - }) - if err != nil { - log.Printf("[%s] invalid cron expression %q: %v", prof.displayName(), prof.Schedule.Cron, err) - ps.errMsg = "Invalid cron: " + prof.Schedule.Cron - } else { - profileMu.Lock() - profileEntryIDs[i] = append(profileEntryIDs[i], eid) - profileMu.Unlock() } } @@ -711,7 +716,7 @@ repoOp := func(status string, args ...string) { idx := getActiveProfile() prof := selectedProfile() - if idx >= maxProfiles || isProfileBusy(idx) { + if idx >= maxProfiles { return } ms := statusItem(idx) @@ -738,13 +743,13 @@ select { case <-mSchedule.ClickedCh: idx := getActiveProfile() prof := selectedProfile() - if idx < maxProfiles && !isProfileBusy(idx) { + if idx < maxProfiles { go runScheduled(idx, statusItem(idx), prof, func() { finishProfile(idx) }) } case <-mBackup.ClickedCh: idx := getActiveProfile() prof := selectedProfile() - if idx < maxProfiles && !isProfileBusy(idx) { + if idx < maxProfiles { go runBackup(idx, statusItem(idx), prof, func() { finishProfile(idx) }) } case <-mCancel.ClickedCh: -- tangled.sh