diff --git a/cmd/bisync/cmd.go b/cmd/bisync/cmd.go index 03fabc199..3ed6a4c58 100644 --- a/cmd/bisync/cmd.go +++ b/cmd/bisync/cmd.go @@ -48,10 +48,12 @@ type Options struct { SaveQueues bool // save extra debugging files (test only flag) IgnoreListingChecksum bool Resilient bool + Recover bool TestFn TestFunc // test-only option, for mocking errors Retries int Compare CompareOpt CompareFlag string + DebugName string } // Default values @@ -125,10 +127,12 @@ func init() { flags.StringVarP(cmdFlags, &Opt.Workdir, "workdir", "", Opt.Workdir, makeHelp("Use custom working dir - useful for testing. (default: {WORKDIR})"), "") flags.StringVarP(cmdFlags, &Opt.BackupDir1, "backup-dir1", "", Opt.BackupDir1, "--backup-dir for Path1. Must be a non-overlapping path on the same remote.", "") flags.StringVarP(cmdFlags, &Opt.BackupDir2, "backup-dir2", "", Opt.BackupDir2, "--backup-dir for Path2. Must be a non-overlapping path on the same remote.", "") + flags.StringVarP(cmdFlags, &Opt.DebugName, "debugname", "", Opt.DebugName, "Debug by tracking one file at various points throughout a bisync run (when -v or -vv)", "") flags.BoolVarP(cmdFlags, &tzLocal, "localtime", "", tzLocal, "Use local time in listings (default: UTC)", "") flags.BoolVarP(cmdFlags, &Opt.NoCleanup, "no-cleanup", "", Opt.NoCleanup, "Retain working files (useful for troubleshooting and testing).", "") flags.BoolVarP(cmdFlags, &Opt.IgnoreListingChecksum, "ignore-listing-checksum", "", Opt.IgnoreListingChecksum, "Do not use checksums for listings (add --ignore-checksum to additionally skip post-copy checksum checks)", "") flags.BoolVarP(cmdFlags, &Opt.Resilient, "resilient", "", Opt.Resilient, "Allow future runs to retry after certain less-serious errors, instead of requiring --resync. Use at your own risk!", "") + flags.BoolVarP(cmdFlags, &Opt.Recover, "recover", "", Opt.Recover, "Automatically recover from interruptions without requiring --resync.", "") flags.IntVarP(cmdFlags, &Opt.Retries, "retries", "", Opt.Retries, "Retry operations this many times if they fail", "") flags.StringVarP(cmdFlags, &Opt.CompareFlag, "compare", "", Opt.CompareFlag, "Comma-separated list of bisync-specific compare options ex. 'size,modtime,checksum' (default: 'size,modtime')", "") flags.BoolVarP(cmdFlags, &Opt.Compare.NoSlowHash, "no-slow-hash", "", Opt.Compare.NoSlowHash, "Ignore listing checksums only on backends where they are slow", "") diff --git a/cmd/bisync/deltas.go b/cmd/bisync/deltas.go index 9a93bd7b7..323d1c799 100644 --- a/cmd/bisync/deltas.go +++ b/cmd/bisync/deltas.go @@ -387,9 +387,12 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change //if files are identical, leave them alone instead of renaming if (dirs1.has(file) || dirs1.has(alias)) && (dirs2.has(file) || dirs2.has(alias)) { - fs.Debugf(nil, "This is a directory, not a file. Skipping equality check and will not rename: %s", file) + fs.Infof(nil, "This is a directory, not a file. Skipping equality check and will not rename: %s", file) ls1.getPut(file, skippedDirs1) ls2.getPut(file, skippedDirs2) + b.debugFn(file, func() { + b.debug(file, fmt.Sprintf("deltas dir: %s, ls1 has name?: %v, ls2 has name?: %v", file, ls1.has(b.DebugName), ls2.has(b.DebugName))) + }) } else { equal := matches.Has(file) if !equal { @@ -499,7 +502,7 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change } // Do the batch operation - if copy2to1.NotEmpty() { + if copy2to1.NotEmpty() && !b.InGracefulShutdown { changes1 = true b.indent("Path2", "Path1", "Do queued copies to") ctx = b.setBackupDir(ctx, 1) @@ -508,7 +511,7 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change // retries, if any results2to1, err = b.retryFastCopy(ctx, b.fs2, b.fs1, copy2to1, "copy2to1", results2to1, err) - if err != nil { + if !b.InGracefulShutdown && err != nil { return } @@ -516,7 +519,7 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change b.syncEmptyDirs(ctx, b.fs1, copy2to1, dirs2, &results2to1, "make") } - if copy1to2.NotEmpty() { + if copy1to2.NotEmpty() && !b.InGracefulShutdown { changes2 = true b.indent("Path1", "Path2", "Do queued copies to") ctx = b.setBackupDir(ctx, 2) @@ -525,7 +528,7 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change // retries, if any results1to2, err = b.retryFastCopy(ctx, b.fs1, b.fs2, copy1to2, "copy1to2", results1to2, err) - if err != nil { + if !b.InGracefulShutdown && err != nil { return } @@ -533,7 +536,7 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change b.syncEmptyDirs(ctx, b.fs2, copy1to2, dirs1, &results1to2, "make") } - if delete1.NotEmpty() { + if delete1.NotEmpty() && !b.InGracefulShutdown { if err = b.saveQueue(delete1, "delete1"); err != nil { return } @@ -541,7 +544,7 @@ func (b *bisyncRun) applyDeltas(ctx context.Context, ds1, ds2 *deltaSet) (change b.syncEmptyDirs(ctx, b.fs1, delete1, dirs1, &results2to1, "remove") } - if delete2.NotEmpty() { + if delete2.NotEmpty() && !b.InGracefulShutdown { if err = b.saveQueue(delete2, "delete2"); err != nil { return } diff --git a/cmd/bisync/listing.go b/cmd/bisync/listing.go index c037f7162..827a2e14c 100644 --- a/cmd/bisync/listing.go +++ b/cmd/bisync/listing.go @@ -17,6 +17,7 @@ import ( "github.com/rclone/rclone/cmd/bisync/bilib" "github.com/rclone/rclone/fs" + "github.com/rclone/rclone/fs/accounting" "github.com/rclone/rclone/fs/filter" "github.com/rclone/rclone/fs/hash" "github.com/rclone/rclone/fs/operations" @@ -368,6 +369,12 @@ func (b *bisyncRun) replaceCurrentListings() { b.handleErr(b.newListing2, "error replacing Path2 listing", bilib.CopyFileIfExists(b.newListing2, b.listing2), true, true) } +// revertToOldListings reverts to the most recent successful listing +func (b *bisyncRun) revertToOldListings() { + b.handleErr(b.listing1, "error reverting to old Path1 listing", bilib.CopyFileIfExists(b.listing1+"-old", b.listing1), true, true) + b.handleErr(b.listing2, "error reverting to old Path2 listing", bilib.CopyFileIfExists(b.listing2+"-old", b.listing2), true, true) +} + func parseHash(str string) (string, string, error) { if str == "-" { return "", "", nil @@ -498,6 +505,12 @@ func (b *bisyncRun) modifyListing(ctx context.Context, src fs.Fs, dst fs.Fs, res } } + b.debugFn(b.DebugName, func() { + var rs ResultsSlice = results + b.debug(b.DebugName, fmt.Sprintf("modifyListing direction: %s, results has name?: %v", direction, rs.has(b.DebugName))) + b.debug(b.DebugName, fmt.Sprintf("modifyListing direction: %s, srcList has name?: %v, dstList has name?: %v", direction, srcList.has(b.DebugName), dstList.has(b.DebugName))) + }) + srcWinners := newFileList() dstWinners := newFileList() errors := newFileList() @@ -657,6 +670,55 @@ func (b *bisyncRun) modifyListing(ctx context.Context, src fs.Fs, dst fs.Fs, res b.recheck(ctxRecheck, src, dst, srcList, dstList, is1to2) } + if b.InGracefulShutdown { + var toKeep []string + var toRollback []string + fs.Debugf(direction, "stats for %s", direction) + trs := accounting.Stats(ctx).Transferred() + for _, tr := range trs { + b.debugFn(tr.Name, func() { + prettyprint(tr, tr.Name, fs.LogLevelInfo) + }) + if tr.Error == nil && tr.Bytes > 0 || tr.Size <= 0 { + prettyprint(tr, "keeping: "+tr.Name, fs.LogLevelDebug) + toKeep = append(toKeep, tr.Name) + } + } + // Dirs (for the unlikely event that the shutdown was triggered post-sync during syncEmptyDirs) + for _, r := range results { + if r.Origin == "syncEmptyDirs" { + if srcWinners.has(r.Name) || dstWinners.has(r.Name) { + toKeep = append(toKeep, r.Name) + fs.Infof(r.Name, "keeping empty dir") + } + } + } + oldSrc, oldDst := b.getOldLists(is1to2) + prettyprint(oldSrc.list, "oldSrc", fs.LogLevelDebug) + prettyprint(oldDst.list, "oldDst", fs.LogLevelDebug) + prettyprint(srcList.list, "srcList", fs.LogLevelDebug) + prettyprint(dstList.list, "dstList", fs.LogLevelDebug) + combinedList := Concat(oldSrc.list, oldDst.list, srcList.list, dstList.list) + for _, f := range combinedList { + if !slices.Contains(toKeep, f) && !slices.Contains(toKeep, b.aliases.Alias(f)) && !b.opt.DryRun { + toRollback = append(toRollback, f) + } + } + b.prepareRollback(toRollback, srcList, dstList, is1to2) + prettyprint(oldSrc.list, "oldSrc", fs.LogLevelDebug) + prettyprint(oldDst.list, "oldDst", fs.LogLevelDebug) + prettyprint(srcList.list, "srcList", fs.LogLevelDebug) + prettyprint(dstList.list, "dstList", fs.LogLevelDebug) + + // clear stats so we only do this once + accounting.MaxCompletedTransfers = 0 + accounting.Stats(ctx).PruneTransfers() + } + + if b.DebugName != "" { + b.debug(b.DebugName, fmt.Sprintf("%s pre-save srcList has it?: %v", direction, srcList.has(b.DebugName))) + b.debug(b.DebugName, fmt.Sprintf("%s pre-save dstList has it?: %v", direction, dstList.has(b.DebugName))) + } // update files err = srcList.save(ctx, srcListing) b.handleErr(srcList, "error saving srcList from modifyListing", err, true, true) @@ -737,8 +799,8 @@ func (b *bisyncRun) recheck(ctxRecheck context.Context, src, dst fs.Fs, srcList, } for _, item := range toRollback { - rollback(item, oldSrc, srcList) - rollback(item, oldDst, dstList) + b.rollback(item, oldSrc, srcList) + b.rollback(item, oldDst, dstList) } } } @@ -750,10 +812,72 @@ func (b *bisyncRun) getListingNames(is1to2 bool) (srcListing string, dstListing return b.listing2, b.listing1 } -func rollback(item string, oldList, newList *fileList) { +func (b *bisyncRun) rollback(item string, oldList, newList *fileList) { + alias := b.aliases.Alias(item) if oldList.has(item) { oldList.getPut(item, newList) + fs.Debugf(nil, "adding to newlist: %s", item) + } else if oldList.has(alias) { + oldList.getPut(alias, newList) + fs.Debugf(nil, "adding to newlist: %s", alias) } else { + fs.Debugf(nil, "removing from newlist: %s (has it?: %v)", item, newList.has(item)) + prettyprint(newList.list, "newList", fs.LogLevelDebug) newList.remove(item) + newList.remove(alias) } } + +func (b *bisyncRun) prepareRollback(toRollback []string, srcList, dstList *fileList, is1to2 bool) { + if len(toRollback) > 0 { + oldSrc, oldDst := b.getOldLists(is1to2) + if b.critical { + return + } + + fs.Debugf("new lists", "src: (%v), dest: (%v)", len(srcList.list), len(dstList.list)) + + for _, item := range toRollback { + b.debugFn(item, func() { + b.debug(item, fmt.Sprintf("pre-rollback oldSrc has it?: %v", oldSrc.has(item))) + b.debug(item, fmt.Sprintf("pre-rollback oldDst has it?: %v", oldDst.has(item))) + b.debug(item, fmt.Sprintf("pre-rollback srcList has it?: %v", srcList.has(item))) + b.debug(item, fmt.Sprintf("pre-rollback dstList has it?: %v", dstList.has(item))) + }) + b.rollback(item, oldSrc, srcList) + b.rollback(item, oldDst, dstList) + b.debugFn(item, func() { + b.debug(item, fmt.Sprintf("post-rollback oldSrc has it?: %v", oldSrc.has(item))) + b.debug(item, fmt.Sprintf("post-rollback oldDst has it?: %v", oldDst.has(item))) + b.debug(item, fmt.Sprintf("post-rollback srcList has it?: %v", srcList.has(item))) + b.debug(item, fmt.Sprintf("post-rollback dstList has it?: %v", dstList.has(item))) + }) + } + } +} + +func (b *bisyncRun) getOldLists(is1to2 bool) (*fileList, *fileList) { + srcListing, dstListing := b.getListingNames(is1to2) + oldSrc, err := b.loadListing(srcListing + "-old") + b.handleErr(oldSrc, "error loading old src listing", err, true, true) + oldDst, err := b.loadListing(dstListing + "-old") + b.handleErr(oldDst, "error loading old dst listing", err, true, true) + fs.Debugf("get old lists", "is1to2: %v, oldsrc: %s (%v), olddest: %s (%v)", is1to2, srcListing+"-old", len(oldSrc.list), dstListing+"-old", len(oldDst.list)) + return oldSrc, oldDst +} + +// Concat returns a new slice concatenating the passed in slices. +func Concat[S ~[]E, E any](ss ...S) S { + size := 0 + for _, s := range ss { + size += len(s) + if size < 0 { + panic("len out of range") + } + } + newslice := slices.Grow[S](nil, size) + for _, s := range ss { + newslice = append(newslice, s...) + } + return newslice +} diff --git a/cmd/bisync/march.go b/cmd/bisync/march.go index 79784fc41..60263e2d5 100644 --- a/cmd/bisync/march.go +++ b/cmd/bisync/march.go @@ -48,6 +48,7 @@ func (b *bisyncRun) makeMarchListing(ctx context.Context) (*fileList, *fileList, if err != nil { b.handleErr("march", "error during march", err, true, true) b.abort = true + return ls1, ls2, err } // save files @@ -160,7 +161,7 @@ func (b *bisyncRun) ForObject(o fs.Object, isPath1 bool) { if b.opt.Compare.Modtime { modtime = o.ModTime(marchCtx).In(TZ) } - id := "" // TODO + id := "" // TODO: ID(o) flags := "-" // "-" for a file and "d" for a directory marchLsLock.Lock() ls.put(o.Remote(), o.Size(), modtime, hashVal, id, flags) @@ -235,3 +236,12 @@ func (b *bisyncRun) findCheckFiles(ctx context.Context) (*fileList, *fileList, e return ls1, ls2, err } + +// ID returns the ID of the Object if known, or "" if not +func ID(o fs.Object) string { + do, ok := o.(fs.IDer) + if !ok { + return "" + } + return do.ID() +} diff --git a/cmd/bisync/operations.go b/cmd/bisync/operations.go index 893b9ca86..714a90f03 100644 --- a/cmd/bisync/operations.go +++ b/cmd/bisync/operations.go @@ -10,10 +10,13 @@ import ( "os" "path/filepath" "strconv" + "strings" gosync "sync" + "time" "github.com/rclone/rclone/cmd/bisync/bilib" "github.com/rclone/rclone/fs" + "github.com/rclone/rclone/fs/accounting" "github.com/rclone/rclone/fs/filter" "github.com/rclone/rclone/fs/operations" "github.com/rclone/rclone/lib/atexit" @@ -25,21 +28,26 @@ var ErrBisyncAborted = errors.New("bisync aborted") // bisyncRun keeps bisync runtime state type bisyncRun struct { - fs1 fs.Fs - fs2 fs.Fs - abort bool - critical bool - retryable bool - basePath string - workDir string - listing1 string - listing2 string - newListing1 string - newListing2 string - aliases bilib.AliasMap - opt *Options - octx context.Context - fctx context.Context + fs1 fs.Fs + fs2 fs.Fs + abort bool + critical bool + retryable bool + basePath string + workDir string + listing1 string + listing2 string + newListing1 string + newListing2 string + aliases bilib.AliasMap + opt *Options + octx context.Context + fctx context.Context + InGracefulShutdown bool + CleanupCompleted bool + SyncCI *fs.ConfigInfo + CancelSync context.CancelFunc + DebugName string } type queues struct { @@ -58,9 +66,10 @@ func Bisync(ctx context.Context, fs1, fs2 fs.Fs, optArg *Options) (err error) { defer resetGlobals() opt := *optArg // ensure that input is never changed b := &bisyncRun{ - fs1: fs1, - fs2: fs2, - opt: &opt, + fs1: fs1, + fs2: fs2, + opt: &opt, + DebugName: opt.DebugName, } if opt.CheckFilename == "" { @@ -119,12 +128,53 @@ func Bisync(ctx context.Context, fs1, fs2 fs.Fs, optArg *Options) (err error) { _ = os.Rename(file, failFile) } } + // waitFor runs fn() until it returns true or the timeout expires + waitFor := func(msg string, totalWait time.Duration, fn func() bool) (ok bool) { + const individualWait = 1 * time.Second + for i := 0; i < int(totalWait/individualWait); i++ { + ok = fn() + if ok { + return ok + } + fs.Infof(nil, Color(terminal.YellowFg, "%s: %v"), msg, int(totalWait/individualWait)-i) + time.Sleep(individualWait) + } + return false + } finalise := func() { finaliseOnce.Do(func() { if atexit.Signalled() { - fs.Logf(nil, "Bisync interrupted. Must run --resync to recover.") - markFailed(b.listing1) - markFailed(b.listing2) + if b.opt.Resync { + fs.Logf(nil, Color(terminal.GreenFg, "No need to gracefully shutdown during --resync (just run it again.)")) + } else { + fs.Logf(nil, Color(terminal.YellowFg, "Attempting to gracefully shutdown. (Send exit signal again for immediate un-graceful shutdown.)")) + b.InGracefulShutdown = true + if b.SyncCI != nil { + fs.Infof(nil, Color(terminal.YellowFg, "Telling Sync to wrap up early.")) + b.SyncCI.MaxTransfer = 1 + b.SyncCI.MaxDuration = 1 * time.Second + b.SyncCI.CutoffMode = fs.CutoffModeSoft + gracePeriod := 30 * time.Second // TODO: flag to customize this? + if !waitFor("Canceling Sync if not done in", gracePeriod, func() bool { return b.CleanupCompleted }) { + fs.Logf(nil, Color(terminal.YellowFg, "Canceling sync and cleaning up")) + b.CancelSync() + waitFor("Aborting Bisync if not done in", 60*time.Second, func() bool { return b.CleanupCompleted }) + } + } else { + // we haven't started to sync yet, so we're good. + // no need to worry about the listing files, as we haven't overwritten them yet. + b.CleanupCompleted = true + fs.Logf(nil, Color(terminal.GreenFg, "Graceful shutdown completed successfully.")) + } + } + if !b.CleanupCompleted { + if !b.opt.Resync { + fs.Logf(nil, Color(terminal.HiRedFg, "Graceful shutdown failed.")) + fs.Logf(nil, Color(terminal.RedFg, "Bisync interrupted. Must run --resync to recover.")) + } + markFailed(b.listing1) + markFailed(b.listing2) + } _ = os.Remove(lockFile) } }) @@ -146,6 +196,17 @@ func Bisync(ctx context.Context, fs1, fs2 fs.Fs, optArg *Options) (err error) { } } + b.CleanupCompleted = true + if b.InGracefulShutdown { + if err == context.Canceled || err == accounting.ErrorMaxTransferLimitReachedGraceful { + err = nil + b.critical = false + } + if err == nil { + fs.Logf(nil, Color(terminal.GreenFg, "Graceful shutdown completed successfully.")) + } + } + if b.critical { if b.retryable && b.opt.Resilient { fs.Errorf(nil, Color(terminal.RedFg, "Bisync critical error: %v"), err) @@ -162,7 +223,7 @@ func Bisync(ctx context.Context, fs1, fs2 fs.Fs, optArg *Options) (err error) { } return ErrBisyncAborted } - if b.abort { + if b.abort && !b.InGracefulShutdown { fs.Logf(nil, Color(terminal.RedFg, "Bisync aborted. Please try again.")) } if err == nil { @@ -221,21 +282,41 @@ func (b *bisyncRun) runLocked(octx context.Context) (err error) { // Check for existence of prior Path1 and Path2 listings if !bilib.FileExists(b.listing1) || !bilib.FileExists(b.listing2) { - // On prior critical error abort, the prior listings are renamed to .lst-err to lock out further runs - b.critical = true - b.retryable = true - errTip := Color(terminal.MagentaFg, "Tip: here are the filenames we were looking for. Do they exist? \n") - errTip += fmt.Sprintf(Color(terminal.CyanFg, "Path1: %s\n"), Color(terminal.HiBlueFg, b.listing1)) - errTip += fmt.Sprintf(Color(terminal.CyanFg, "Path2: %s\n"), Color(terminal.HiBlueFg, b.listing2)) - errTip += Color(terminal.MagentaFg, "Try running this command to inspect the work dir: \n") - errTip += fmt.Sprintf(Color(terminal.HiCyanFg, "rclone lsl \"%s\""), b.workDir) + if b.opt.Recover && bilib.FileExists(b.listing1+"-old") && bilib.FileExists(b.listing2+"-old") { + errTip := fmt.Sprintf(Color(terminal.CyanFg, "Path1: %s\n"), Color(terminal.HiBlueFg, b.listing1)) + errTip += fmt.Sprintf(Color(terminal.CyanFg, "Path2: %s"), Color(terminal.HiBlueFg, b.listing2)) + fs.Logf(nil, Color(terminal.YellowFg, "Listings not found. Reverting to prior backup as --recover is set. \n")+errTip) + if opt.CheckSync != CheckSyncFalse { + // Run CheckSync to ensure old listing is valid (garbage in, garbage out!) + fs.Infof(nil, "Validating backup listings for Path1 %s vs Path2 %s", quotePath(path1), quotePath(path2)) + if err = b.checkSync(b.listing1+"-old", b.listing2+"-old"); err != nil { + b.critical = true + b.retryable = true + return err + } + fs.Infof(nil, Color(terminal.GreenFg, "Backup listing is valid.")) + } + b.revertToOldListings() + } else { + // On prior critical error abort, the prior listings are renamed to .lst-err to lock out further runs + b.critical = true + b.retryable = true + errTip := Color(terminal.MagentaFg, "Tip: here are the filenames we were looking for. Do they exist? \n") + errTip += fmt.Sprintf(Color(terminal.CyanFg, "Path1: %s\n"), Color(terminal.HiBlueFg, b.listing1)) + errTip += fmt.Sprintf(Color(terminal.CyanFg, "Path2: %s\n"), Color(terminal.HiBlueFg, b.listing2)) + errTip += Color(terminal.MagentaFg, "Try running this command to inspect the work dir: \n") + errTip += fmt.Sprintf(Color(terminal.HiCyanFg, "rclone lsl \"%s\""), b.workDir) - return errors.New("cannot find prior Path1 or Path2 listings, likely due to critical error on prior run \n" + errTip) + return errors.New("cannot find prior Path1 or Path2 listings, likely due to critical error on prior run \n" + errTip) + } } fs.Infof(nil, "Building Path1 and Path2 listings") ls1, ls2, err = b.makeMarchListing(fctx) - if err != nil { + if err != nil || accounting.Stats(fctx).Errored() { + fs.Errorf(nil, Color(terminal.RedFg, "There were errors while building listings. Aborting as it is too dangerous to continue.")) + b.critical = true + b.retryable = true return err } @@ -306,31 +387,50 @@ func (b *bisyncRun) runLocked(octx context.Context) (err error) { fs.Infof(nil, "Applying changes") changes1, changes2, results2to1, results1to2, queues, err = b.applyDeltas(octx, ds1, ds2) if err != nil { - b.critical = true - // b.retryable = true // not sure about this one - return err + if b.InGracefulShutdown && (err == context.Canceled || err == accounting.ErrorMaxTransferLimitReachedGraceful || strings.Contains(err.Error(), "context canceled")) { + fs.Infof(nil, "Ignoring sync error due to Graceful Shutdown: %v", err) + } else { + b.critical = true + // b.retryable = true // not sure about this one + return err + } } } // Clean up and check listings integrity fs.Infof(nil, "Updating listings") var err1, err2 error + if b.DebugName != "" { + l1, _ := b.loadListing(b.listing1) + l2, _ := b.loadListing(b.listing2) + newl1, _ := b.loadListing(b.newListing1) + newl2, _ := b.loadListing(b.newListing2) + b.debug(b.DebugName, fmt.Sprintf("pre-saveOldListings, ls1 has name?: %v, ls2 has name?: %v", l1.has(b.DebugName), l2.has(b.DebugName))) + b.debug(b.DebugName, fmt.Sprintf("pre-saveOldListings, newls1 has name?: %v, newls2 has name?: %v", newl1.has(b.DebugName), newl2.has(b.DebugName))) + } b.saveOldListings() // save new listings + // NOTE: "changes" in this case does not mean this run vs. last run, it means start of this run vs. end of this run. + // i.e. whether we can use the March lst-new as this side's lst without modifying it. if noChanges { b.replaceCurrentListings() } else { - if changes1 { // 2to1 + if changes1 || b.InGracefulShutdown { // 2to1 err1 = b.modifyListing(fctx, b.fs2, b.fs1, results2to1, queues, false) } else { err1 = bilib.CopyFileIfExists(b.newListing1, b.listing1) } - if changes2 { // 1to2 + if changes2 || b.InGracefulShutdown { // 1to2 err2 = b.modifyListing(fctx, b.fs1, b.fs2, results1to2, queues, true) } else { err2 = bilib.CopyFileIfExists(b.newListing2, b.listing2) } } + if b.DebugName != "" { + l1, _ := b.loadListing(b.listing1) + l2, _ := b.loadListing(b.listing2) + b.debug(b.DebugName, fmt.Sprintf("post-modifyListing, ls1 has name?: %v, ls2 has name?: %v", l1.has(b.DebugName), l2.has(b.DebugName))) + } err = err1 if err == nil { err = err2 @@ -609,6 +709,18 @@ func (b *bisyncRun) setBackupDir(ctx context.Context, destPath int) context.Cont return ctx } +func (b *bisyncRun) debug(nametocheck, msgiftrue string) { + if b.DebugName != "" && b.DebugName == nametocheck { + fs.Infof(Color(terminal.MagentaBg, "DEBUGNAME "+b.DebugName), Color(terminal.MagentaBg, msgiftrue)) + } +} + +func (b *bisyncRun) debugFn(nametocheck string, fn func()) { + if b.DebugName != "" && b.DebugName == nametocheck { + fn() + } +} + // mainly to make sure tests don't interfere with each other when running more than one func resetGlobals() { downloadHash = false diff --git a/cmd/bisync/queue.go b/cmd/bisync/queue.go index 6f181e1a9..120b9e9bd 100644 --- a/cmd/bisync/queue.go +++ b/cmd/bisync/queue.go @@ -11,6 +11,7 @@ import ( "github.com/rclone/rclone/cmd/bisync/bilib" "github.com/rclone/rclone/fs" + "github.com/rclone/rclone/fs/accounting" "github.com/rclone/rclone/fs/filter" "github.com/rclone/rclone/fs/hash" "github.com/rclone/rclone/fs/operations" @@ -35,6 +36,19 @@ type Results struct { IsWinner bool IsSrc bool IsDst bool + Origin string +} + +// ResultsSlice is a slice of Results (obviously) +type ResultsSlice []Results + +func (rs *ResultsSlice) has(name string) bool { + for _, r := range *rs { + if r.Name == name { + return true + } + } + return false } var logger = operations.NewLoggerOpt() @@ -96,10 +110,11 @@ func WriteResults(ctx context.Context, sigil operations.Sigil, src, dst fs.DirEn opt := operations.GetLoggerOpt(ctx) result := Results{ - Sigil: sigil, - Src: FsPathIfAny(src), - Dst: FsPathIfAny(dst), - Err: err, + Sigil: sigil, + Src: FsPathIfAny(src), + Dst: FsPathIfAny(dst), + Err: err, + Origin: "sync", } result.Winner = operations.WinningSide(ctx, sigil, src, dst, err) @@ -202,6 +217,9 @@ func (b *bisyncRun) preCopy(ctx context.Context) context.Context { } func (b *bisyncRun) fastCopy(ctx context.Context, fsrc, fdst fs.Fs, files bilib.Names, queueName string) ([]Results, error) { + if b.InGracefulShutdown { + return nil, nil + } ctx = b.preCopy(ctx) if err := b.saveQueue(files, queueName); err != nil { return nil, err @@ -220,6 +238,9 @@ func (b *bisyncRun) fastCopy(ctx context.Context, fsrc, fdst fs.Fs, files bilib. } } + b.SyncCI = fs.GetConfig(ctxCopy) // allows us to request graceful shutdown + accounting.MaxCompletedTransfers = -1 // we need a complete list in the event of graceful shutdown + ctxCopy, b.CancelSync = context.WithCancel(ctxCopy) b.testFn() err := sync.Sync(ctxCopy, fdst, fsrc, b.opt.CreateEmptySrcDirs) prettyprint(logger, "logger", fs.LogLevelDebug) @@ -236,7 +257,7 @@ func (b *bisyncRun) fastCopy(ctx context.Context, fsrc, fdst fs.Fs, files bilib. } func (b *bisyncRun) retryFastCopy(ctx context.Context, fsrc, fdst fs.Fs, files bilib.Names, queueName string, results []Results, err error) ([]Results, error) { - if err != nil && b.opt.Resilient && b.opt.Retries > 1 { + if err != nil && b.opt.Resilient && !b.InGracefulShutdown && b.opt.Retries > 1 { for tries := 1; tries <= b.opt.Retries; tries++ { fs.Logf(queueName, Color(terminal.YellowFg, "Received error: %v - retrying as --resilient is set. Retry %d/%d"), err, tries, b.opt.Retries) results, err = b.fastCopy(ctx, fsrc, fdst, files, queueName) @@ -259,6 +280,10 @@ func (b *bisyncRun) resyncDir(ctx context.Context, fsrc, fdst fs.Fs) ([]Results, // operation should be "make" or "remove" func (b *bisyncRun) syncEmptyDirs(ctx context.Context, dst fs.Fs, candidates bilib.Names, dirsList *fileList, results *[]Results, operation string) { + if b.InGracefulShutdown { + return + } + fs.Debugf(nil, "syncing empty dirs") if b.opt.CreateEmptySrcDirs && (!b.opt.Resync || operation == "make") { candidatesList := candidates.ToList() @@ -272,10 +297,11 @@ func (b *bisyncRun) syncEmptyDirs(ctx context.Context, dst fs.Fs, candidates bil if dirsList.has(s) { //make sure it's a dir, not a file r := Results{} r.Name = s - r.Size = 0 + r.Size = -1 r.Modtime = dirsList.getTime(s).In(time.UTC) r.Flags = "d" r.Err = nil + r.Origin = "syncEmptyDirs" r.Winner = operations.Winner{ // note: Obj not set Side: "src", Err: nil, diff --git a/docs/content/bisync.md b/docs/content/bisync.md index 704d992a9..5778a1e5f 100644 --- a/docs/content/bisync.md +++ b/docs/content/bisync.md @@ -507,6 +507,40 @@ Certain more serious errors will still enforce a `--resync` lockout, even in `-- Behavior of `--resilient` may change in a future version. +### --recover + +If `--recover` is set, in the event of a sudden interruption or other +un-graceful shutdown, bisync will attempt to automatically recover on the next +run, instead of requiring `--resync`. Bisync is able to recover robustly by +keeping one "backup" listing at all times, representing the state of both paths +after the last known successful sync. Bisync can then compare the current state +with this snapshot to determine which changes it needs to retry. Changes that +were synced after this snapshot (during the run that was later interrupted) +will appear to bisync as if they are "new or changed on both sides", but in +most cases this is not a problem, as bisync will simply do its usual "equality +check" and learn that no action needs to be taken on these files, since they +are already identical on both sides. + +In the rare event that a file is synced successfully during a run that later +aborts, and then that same file changes AGAIN before the next run, bisync will +think it is a sync conflict, and handle it accordingly. (From bisync's +perspective, the file has changed on both sides since the last trusted sync, +and the files on either side are not currently identical.) Therefore, +`--recover` carries with it a slightly increased chance of having conflicts -- +though in practice this is pretty rare, as the conditions required to cause it +are quite specific. This risk can be reduced by using bisync's ["Graceful +Shutdown"](#graceful-shutdown) mode (triggered by sending `SIGINT` or +`Ctrl+C`), when you have the choice, instead of forcing a sudden termination. + +`--recover` and `--resilient` are similar, but distinct -- the main difference +is that `--resilient` is about _retrying_, while `--recover` is about +_recovering_. Most users will probably want both. `--resilient` allows retrying +when bisync has chosen to abort itself due to safety features such as failing +`--check-access` or detecting a filter change. `--resilient` does not cover +external interruptions such as a user shutting down their computer in the +middle of a sync -- that is what `--recover` is for. + + ### --backup-dir1 and --backup-dir2 As of `v1.66`, [`--backup-dir`](/docs/#backup-dir-dir) is supported in bisync. @@ -670,6 +704,31 @@ lest there be replicated files, deleted files and general mayhem. - `1` for a non-critical failing run (a rerun may be successful), - `2` for a critically aborted run (requires a `--resync` to recover). +### Graceful Shutdown + +Bisync has a "Graceful Shutdown" mode which is activated by sending `SIGINT` or +pressing `Ctrl+C` during a run. Once triggered, bisync will use best efforts to +exit cleanly before the timer runs out. If bisync is in the middle of +transferring files, it will attempt to cleanly empty its queue by finishing +what it has started but not taking more. If it cannot do so within 30 seconds, +it will cancel the in-progress transfers at that point and then give itself a +maximum of 60 seconds to wrap up, save its state for next time, and exit. With +the `-vP` flags you will see constant status updates and a final confirmation +of whether or not the graceful shutdown was successful. + +At any point during the "Graceful Shutdown" sequence, a second `SIGINT` or +`Ctrl+C` will trigger an immediate, un-graceful exit, which will leave things +in a messier state. Usually a robust recovery will still be possible if using +[`--recover`](#recover) mode, otherwise you will need to do a `--resync`. + +If you plan to use Graceful Shutdown mode, it is recommended to use +[`--resilient`](#resilient) and [`--recover`](#recover), and it is important to +NOT use [`--inplace`](/docs/#inplace), otherwise you risk leaving +partially-written files on one side, which may be confused for real files on +the next run. Note also that in the event of an abrupt interruption, a [lock +file](#lock-file) will be left behind to block concurrent runs. You will need +to delete it before you can proceed with the next run. + ## Limitations ### Supported backends @@ -1498,6 +1557,8 @@ for performance improvements and less [risk of error](https://forum.rclone.org/t instead of of `--size-only`, when `check` is not available. * Bisync no longer fails to find the correct listing file when configs are overridden with backend-specific flags. * Bisync now fully supports comparing based on any combination of size, modtime, and checksum, lifting the prior restriction on backends without modtime support. +* Bisync now supports a "Graceful Shutdown" mode to cleanly cancel a run early without requiring `--resync`. +* New `--recover` flag allows robust recovery in the event of interruptions, without requiring `--resync`. ### `v1.64` * Fixed an [issue](https://forum.rclone.org/t/bisync-bugs-and-feature-requests/37636#:~:text=1.%20Dry%20runs%20are%20not%20completely%20dry)