lib/model: Centralize error reporting, modified files are errors (fixes #4392)

lib/model/rwfolder.go

@@ -251,9 +251,6 @@ func (f *sendReceiveFolder) Serve() {
 					// errors preventing us. Flag this with a warning and
 					// wait a bit longer before retrying.
 					if folderErrors := f.currentErrors(); len(folderErrors) > 0 {
-						for _, fileError := range folderErrors {
-							l.Infof("Puller (folder %v, dir %q): %v", f.Description(), fileError.Path, fileError.Err)
-						}
 						events.Default.Log(events.FolderErrors, map[string]interface{}{
 							"folder": f.folderID,
 							"errors": folderErrors,
@@ -369,7 +366,7 @@ func (f *sendReceiveFolder) pullerIteration(ignores *ignore.Matcher) int {
 		if err := fileValid(intf); err != nil {
 			// The file isn't valid so we can't process it. Pretend that we
 			// tried and set the error for the file.
-			f.newError(intf.FileName(), err)
+			f.newError("need", intf.FileName(), err)
 			changed++
 			return true
 		}
@@ -418,7 +415,7 @@ func (f *sendReceiveFolder) pullerIteration(ignores *ignore.Matcher) int {
 		// Verify that the thing we are handling lives inside a directory,
 		// and not a symlink or empty space.
 		if err := osutil.TraversesSymlink(f.fs, filepath.Dir(fi.Name)); err != nil {
-			f.newError(fi.Name, err)
+			f.newError("traverses d", fi.Name, err)
 			continue
 		}
 
@@ -507,7 +504,7 @@ nextFile:
 		// Verify that the thing we are handling lives inside a directory,
 		// and not a symlink or empty space.
 		if err := osutil.TraversesSymlink(f.fs, filepath.Dir(fi.Name)); err != nil {
-			f.newError(fi.Name, err)
+			f.newError("traverses q", fi.Name, err)
 			continue
 		}
 
@@ -611,8 +608,7 @@ func (f *sendReceiveFolder) handleDir(file protocol.FileInfo) {
 	case err == nil && (!info.IsDir() || info.IsSymlink()):
 		err = osutil.InWritableDir(f.fs.Remove, f.fs, file.Name)
 		if err != nil {
-			l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-			f.newError(file.Name, err)
+			f.newError("dir replace", file.Name, err)
 			return
 		}
 		fallthrough
@@ -642,15 +638,13 @@ func (f *sendReceiveFolder) handleDir(file protocol.FileInfo) {
 		if err = osutil.InWritableDir(mkdir, f.fs, file.Name); err == nil {
 			f.dbUpdates <- dbUpdateJob{file, dbUpdateHandleDir}
 		} else {
-			l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-			f.newError(file.Name, err)
+			f.newError("dir mkdir", file.Name, err)
 		}
 		return
 	// Weird error when stat()'ing the dir. Probably won't work to do
 	// anything else with it if we can't even stat() it.
 	case err != nil:
-		l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-		f.newError(file.Name, err)
+		f.newError("dir stat", file.Name, err)
 		return
 	}
 
@@ -662,8 +656,7 @@ func (f *sendReceiveFolder) handleDir(file protocol.FileInfo) {
 	} else if err := f.fs.Chmod(file.Name, mode|(fs.FileMode(info.Mode())&retainBits)); err == nil {
 		f.dbUpdates <- dbUpdateJob{file, dbUpdateHandleDir}
 	} else {
-		l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-		f.newError(file.Name, err)
+		f.newError("dir chmod", file.Name, err)
 	}
 }
 
@@ -699,8 +692,7 @@ func (f *sendReceiveFolder) handleSymlink(file protocol.FileInfo) {
 		// Index entry from a Syncthing predating the support for including
 		// the link target in the index entry. We log this as an error.
 		err = errors.New("incompatible symlink entry; rescan with newer Syncthing on source")
-		l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-		f.newError(file.Name, err)
+		f.newError("symlink", file.Name, err)
 		return
 	}
 
@@ -710,8 +702,7 @@ func (f *sendReceiveFolder) handleSymlink(file protocol.FileInfo) {
 		// path.
 		err = osutil.InWritableDir(f.fs.Remove, f.fs, file.Name)
 		if err != nil {
-			l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-			f.newError(file.Name, err)
+			f.newError("symlink remove", file.Name, err)
 			return
 		}
 	}
@@ -725,8 +716,7 @@ func (f *sendReceiveFolder) handleSymlink(file protocol.FileInfo) {
 	if err = osutil.InWritableDir(createLink, f.fs, file.Name); err == nil {
 		f.dbUpdates <- dbUpdateJob{file, dbUpdateHandleSymlink}
 	} else {
-		l.Debugf("Puller (folder %q, dir %q): %v", f.folderID, file.Name, err)
-		f.newError(file.Name, err)
+		f.newError("symlink create", file.Name, err)
 	}
 }
 
@@ -774,8 +764,7 @@ func (f *sendReceiveFolder) deleteDir(file protocol.FileInfo, matcher *ignore.Ma
 		// file and not a directory etc) and that the delete is handled.
 		f.dbUpdates <- dbUpdateJob{file, dbUpdateDeleteDir}
 	} else {
-		l.Debugf("Puller (folder %q, dir %q): delete: %v", f.folderID, file.Name, err)
-		f.newError(file.Name, err)
+		f.newError("delete dir", file.Name, err)
 	}
 }
 
@@ -827,8 +816,7 @@ func (f *sendReceiveFolder) deleteFile(file protocol.FileInfo) {
 		// not a directory etc) and that the delete is handled.
 		f.dbUpdates <- dbUpdateJob{file, dbUpdateDeleteFile}
 	} else {
-		l.Debugf("Puller (folder %q, file %q): delete: %v", f.folderID, file.Name, err)
-		f.newError(file.Name, err)
+		f.newError("delete file", file.Name, err)
 	}
 }
 
@@ -894,8 +882,8 @@ func (f *sendReceiveFolder) renameFile(source, target protocol.FileInfo) {
 
 		err = f.shortcutFile(target)
 		if err != nil {
-			l.Debugf("Puller (folder %q, file %q): rename from %q metadata: %v", f.folderID, target.Name, source.Name, err)
-			f.newError(target.Name, err)
+			err = fmt.Errorf("from %s: %s", source.Name, err.Error())
+			f.newError("rename shortcut", target.Name, err)
 			return
 		}
 
@@ -907,8 +895,8 @@ func (f *sendReceiveFolder) renameFile(source, target protocol.FileInfo) {
 
 		err = osutil.InWritableDir(f.fs.Remove, f.fs, source.Name)
 		if err != nil {
-			l.Debugf("Puller (folder %q, file %q): delete %q after failed rename: %v", f.folderID, target.Name, source.Name, err)
-			f.newError(target.Name, err)
+			err = fmt.Errorf("from %s: %s", source.Name, err.Error())
+			f.newError("rename delete", target.Name, err)
 			return
 		}
 
@@ -982,8 +970,7 @@ func (f *sendReceiveFolder) handleFile(file protocol.FileInfo, copyChan chan<- c
 		})
 
 		if err != nil {
-			l.Debugln("Puller: shortcut:", err)
-			f.newError(file.Name, err)
+			f.newError("shortcut", file.Name, err)
 		} else {
 			f.dbUpdates <- dbUpdateJob{file, dbUpdateShortcutFile}
 		}
@@ -1040,7 +1027,7 @@ func (f *sendReceiveFolder) handleFile(file protocol.FileInfo, copyChan chan<- c
 	if f.MinDiskFree.BaseValue() > 0 {
 		if usage, err := f.fs.Usage("."); err == nil && usage.Free < blocksSize {
 			l.Warnf(`Folder "%s": insufficient disk space in %s for %s: have %.2f MiB, need %.2f MiB`, f.folderID, f.fs.URI(), file.Name, float64(usage.Free)/1024/1024, float64(blocksSize)/1024/1024)
-			f.newError(file.Name, errors.New("insufficient space"))
+			f.newError("disk space", file.Name, errors.New("insufficient space"))
 			return
 		}
 	}
@@ -1093,8 +1080,7 @@ func (f *sendReceiveFolder) handleFile(file protocol.FileInfo, copyChan chan<- c
 func (f *sendReceiveFolder) shortcutFile(file protocol.FileInfo) error {
 	if !f.ignorePermissions(file) {
 		if err := f.fs.Chmod(file.Name, fs.FileMode(file.Permissions&0777)); err != nil {
-			l.Debugf("Puller (folder %q, file %q): shortcut: chmod: %v", f.folderID, file.Name, err)
-			f.newError(file.Name, err)
+			f.newError("shortcut chmod", file.Name, err)
 			return err
 		}
 	}
@@ -1384,7 +1370,7 @@ func (f *sendReceiveFolder) performFinish(state *sharedPullerState) error {
 			// for this file up to ten times, but the last nine of those
 			// scans will be cheap...
 			go f.Scan([]string{state.curFile.Name})
-			return nil
+			return fmt.Errorf("file modified but not rescanned; will try again later")
 		}
 
 		switch {
@@ -1452,8 +1438,7 @@ func (f *sendReceiveFolder) finisherRoutine(in <-chan *sharedPullerState) {
 			}
 
 			if err != nil {
-				l.Debugln("Puller: final:", err)
-				f.newError(state.file.Name, err)
+				f.newError("finisher", state.file.Name, err)
 			} else {
 				f.blockStatsMut.Lock()
 				f.blockStats["total"] += state.reused + state.copyTotal + state.pullTotal
@@ -1464,6 +1449,7 @@ func (f *sendReceiveFolder) finisherRoutine(in <-chan *sharedPullerState) {
 				f.blockStats["copyElsewhere"] += state.copyTotal - state.copyOrigin
 				f.blockStatsMut.Unlock()
 			}
+
 			events.Default.Log(events.ItemFinished, map[string]interface{}{
 				"folder": f.folderID,
 				"item":   state.file.Name,
@@ -1665,7 +1651,7 @@ func (f *sendReceiveFolder) moveForConflict(name string, lastModBy string) error
 	return err
 }
 
-func (f *sendReceiveFolder) newError(path string, err error) {
+func (f *sendReceiveFolder) newError(context, path string, err error) {
 	f.errorsMut.Lock()
 	defer f.errorsMut.Unlock()
 
@@ -1675,8 +1661,8 @@ func (f *sendReceiveFolder) newError(path string, err error) {
 	if _, ok := f.errors[path]; ok {
 		return
 	}
-
-	f.errors[path] = err.Error()
+	l.Infof("Puller (folder %q, file %q): %s: %v", f.Description(), path, context, err)
+	f.errors[path] = fmt.Sprintf("%s: %s", context, err.Error())
 }
 
 func (f *sendReceiveFolder) clearErrors() {

lib/model/sharedpullerstate.go

@@ -7,6 +7,7 @@
 package model
 
 import (
+	"fmt"
 	"io"
 	"path/filepath"
 	"time"
@@ -204,9 +205,8 @@ func (s *sharedPullerState) sourceFile() (fs.File, error) {
 	return fd, nil
 }
 
-// earlyClose prints a warning message composed of the context and
-// error, and marks the sharedPullerState as failed. Is a no-op when called on
-// an already failed state.
+// fail sets the error on the puller state compose of error, and marks the
+// sharedPullerState as failed. Is a no-op when called on an already failed state.
 func (s *sharedPullerState) fail(context string, err error) {
 	s.mut.Lock()
 	defer s.mut.Unlock()
@@ -215,12 +215,11 @@ func (s *sharedPullerState) fail(context string, err error) {
 }
 
 func (s *sharedPullerState) failLocked(context string, err error) {
-	if s.err != nil {
+	if s.err != nil || err == nil {
 		return
 	}
 
-	l.Infof("Puller (folder %q, file %q): %s: %v", s.folder, s.file.Name, context, err)
-	s.err = err
+	s.err = fmt.Errorf("%s: %s", context, err.Error())
 }
 
 func (s *sharedPullerState) failed() error {