lib/scanner: More sensible debug output (#8596)

Previous debug input didn't really give enough info to show what was
happening, while it also printed full block lists which are enormously
verbose. Now it consistently prints 1. what it sees on disk, 2. what it
got from CurrentFile (without blocks), 3. the action taken on that file.

lib/protocol/bep_extensions.go

@@ -58,8 +58,8 @@ func (f FileInfo) String() string {
 		return fmt.Sprintf("Directory{Name:%q, Sequence:%d, Permissions:0%o, ModTime:%v, Version:%v, VersionHash:%x, Deleted:%v, Invalid:%v, LocalFlags:0x%x, NoPermissions:%v, Platform:%v, InodeChangeTime:%v}",
 			f.Name, f.Sequence, f.Permissions, f.ModTime(), f.Version, f.VersionHash, f.Deleted, f.RawInvalid, f.LocalFlags, f.NoPermissions, f.Platform, f.InodeChangeTime())
 	case FileInfoTypeFile:
-		return fmt.Sprintf("File{Name:%q, Sequence:%d, Permissions:0%o, ModTime:%v, Version:%v, VersionHash:%x, Length:%d, Deleted:%v, Invalid:%v, LocalFlags:0x%x, NoPermissions:%v, BlockSize:%d, Blocks:%v, BlocksHash:%x, Platform:%v, InodeChangeTime:%v}",
-			f.Name, f.Sequence, f.Permissions, f.ModTime(), f.Version, f.VersionHash, f.Size, f.Deleted, f.RawInvalid, f.LocalFlags, f.NoPermissions, f.RawBlockSize, f.Blocks, f.BlocksHash, f.Platform, f.InodeChangeTime())
+		return fmt.Sprintf("File{Name:%q, Sequence:%d, Permissions:0%o, ModTime:%v, Version:%v, VersionHash:%x, Length:%d, Deleted:%v, Invalid:%v, LocalFlags:0x%x, NoPermissions:%v, BlockSize:%d, NumBlocks:%d, BlocksHash:%x, Platform:%v, InodeChangeTime:%v}",
+			f.Name, f.Sequence, f.Permissions, f.ModTime(), f.Version, f.VersionHash, f.Size, f.Deleted, f.RawInvalid, f.LocalFlags, f.NoPermissions, f.RawBlockSize, len(f.Blocks), f.BlocksHash, f.Platform, f.InodeChangeTime())
 	case FileInfoTypeSymlink, FileInfoTypeSymlinkDirectory, FileInfoTypeSymlinkFile:
 		return fmt.Sprintf("Symlink{Name:%q, Type:%v, Sequence:%d, Version:%v, VersionHash:%x, Deleted:%v, Invalid:%v, LocalFlags:0x%x, NoPermissions:%v, SymlinkTarget:%q, Platform:%v, InodeChangeTime:%v}",
 			f.Name, f.Type, f.Sequence, f.Version, f.VersionHash, f.Deleted, f.RawInvalid, f.LocalFlags, f.NoPermissions, f.SymlinkTarget, f.Platform, f.InodeChangeTime())

lib/scanner/blockqueue.go

@@ -98,6 +98,8 @@ func (ph *parallelHasher) hashFiles(ctx context.Context) {
 				return
 			}
 
+			l.Debugln("started hashing:", f)
+
 			if f.IsDirectory() || f.IsDeleted() {
 				panic("Bug. Asked to hash a directory or a deleted file.")
 			}
@@ -120,6 +122,7 @@ func (ph *parallelHasher) hashFiles(ctx context.Context) {
 				f.Size += int64(b.Size)
 			}
 
+			l.Debugln("completed hashing:", f)
 			select {
 			case ph.outbox <- ScanResult{File: f}:
 			case <-ctx.Done():

lib/scanner/walk.go

@@ -399,6 +399,7 @@ func (w *walker) walkRegular(ctx context.Context, relPath string, info fs.FileIn
 	f = w.updateFileInfo(f, curFile)
 	f.NoPermissions = w.IgnorePerms
 	f.RawBlockSize = blockSize
+	l.Debugln(w, "checking:", f)
 
 	if hasCurFile {
 		if curFile.IsEquivalentOptional(f, protocol.FileInfoComparison{
@@ -409,7 +410,7 @@ func (w *walker) walkRegular(ctx context.Context, relPath string, info fs.FileIn
 			IgnoreOwnership: !w.ScanOwnership,
 			IgnoreXattrs:    !w.ScanXattrs,
 		}) {
-			l.Debugln(w, "unchanged:", curFile, info.ModTime().Unix(), info.Mode()&fs.ModePerm)
+			l.Debugln(w, "unchanged:", curFile)
 			return nil
 		}
 		if curFile.ShouldConflict() {
@@ -420,7 +421,7 @@ func (w *walker) walkRegular(ctx context.Context, relPath string, info fs.FileIn
 			// conflict.
 			f.Version = f.Version.DropOthers(w.ShortID)
 		}
-		l.Debugln(w, "rescan:", curFile, info.ModTime().Unix(), info.Mode()&fs.ModePerm)
+		l.Debugln(w, "rescan:", curFile)
 	}
 
 	l.Debugln(w, "to hash:", relPath, f)
@@ -443,6 +444,7 @@ func (w *walker) walkDir(ctx context.Context, relPath string, info fs.FileInfo,
 	}
 	f = w.updateFileInfo(f, curFile)
 	f.NoPermissions = w.IgnorePerms
+	l.Debugln(w, "checking:", f)
 
 	if hasCurFile {
 		if curFile.IsEquivalentOptional(f, protocol.FileInfoComparison{
@@ -453,7 +455,7 @@ func (w *walker) walkDir(ctx context.Context, relPath string, info fs.FileInfo,
 			IgnoreOwnership: !w.ScanOwnership,
 			IgnoreXattrs:    !w.ScanXattrs,
 		}) {
-			l.Debugln(w, "unchanged:", curFile, info.ModTime().Unix(), info.Mode()&fs.ModePerm)
+			l.Debugln(w, "unchanged:", curFile)
 			return nil
 		}
 		if curFile.ShouldConflict() {
@@ -464,6 +466,7 @@ func (w *walker) walkDir(ctx context.Context, relPath string, info fs.FileInfo,
 			// conflict.
 			f.Version = f.Version.DropOthers(w.ShortID)
 		}
+		l.Debugln(w, "rescan:", curFile)
 	}
 
 	l.Debugln(w, "dir:", relPath, f)
@@ -493,8 +496,8 @@ func (w *walker) walkSymlink(ctx context.Context, relPath string, info fs.FileIn
 	}
 
 	curFile, hasCurFile := w.CurrentFiler.CurrentFile(relPath)
-
 	f = w.updateFileInfo(f, curFile)
+	l.Debugln(w, "checking:", f)
 
 	if hasCurFile {
 		if curFile.IsEquivalentOptional(f, protocol.FileInfoComparison{
@@ -516,9 +519,10 @@ func (w *walker) walkSymlink(ctx context.Context, relPath string, info fs.FileIn
 			// conflict.
 			f.Version = f.Version.DropOthers(w.ShortID)
 		}
+		l.Debugln(w, "rescan:", curFile)
 	}
 
-	l.Debugln(w, "symlink changedb:", relPath, f)
+	l.Debugln(w, "symlink:", relPath, f)
 
 	select {
 	case finishedChan <- ScanResult{File: f}: