From ed588ce335877b31f864581bd130d9fa528fd36e Mon Sep 17 00:00:00 2001 From: Jakob Borg Date: Thu, 13 Oct 2022 19:32:58 +0200 Subject: [PATCH] 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 | 4 ++-- lib/scanner/blockqueue.go | 3 +++ lib/scanner/walk.go | 14 +++++++++----- 3 files changed, 14 insertions(+), 7 deletions(-) diff --git a/lib/protocol/bep_extensions.go b/lib/protocol/bep_extensions.go index 5a835e976..d2a0cad35 100644 --- a/lib/protocol/bep_extensions.go +++ b/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()) diff --git a/lib/scanner/blockqueue.go b/lib/scanner/blockqueue.go index 7eaa60307..4e4517628 100644 --- a/lib/scanner/blockqueue.go +++ b/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(): diff --git a/lib/scanner/walk.go b/lib/scanner/walk.go index 7a782a21a..b155925ca 100644 --- a/lib/scanner/walk.go +++ b/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}: