From b2f4f52b642ed6b9d70849156e93145d16956a9f Mon Sep 17 00:00:00 2001 From: Nick Craig-Wood Date: Mon, 6 Jul 2020 16:06:42 +0100 Subject: [PATCH] vfs cache: make logging consistent and remove some debug logging --- vfs/vfscache/cache.go | 16 ++++----- vfs/vfscache/downloaders/downloaders.go | 33 +++++++++---------- vfs/vfscache/item.go | 43 ++++++++++++------------- vfs/vfscache/writeback/writeback.go | 13 ++++---- 4 files changed, 52 insertions(+), 53 deletions(-) diff --git a/vfs/vfscache/cache.go b/vfs/vfscache/cache.go index e6f7454a6..a6cf6eb45 100644 --- a/vfs/vfscache/cache.go +++ b/vfs/vfscache/cache.go @@ -73,9 +73,9 @@ func New(ctx context.Context, fremote fs.Fs, opt *vfscommon.Options, avFn AddVir fRoot = strings.Replace(fRoot, ":", "", -1) } root := file.UNCPath(filepath.Join(config.CacheDir, "vfs", fremote.Name(), fRoot)) - fs.Debugf(nil, "vfs cache root is %q", root) + fs.Debugf(nil, "vfs cache: root is %q", root) metaRoot := file.UNCPath(filepath.Join(config.CacheDir, "vfsMeta", fremote.Name(), fRoot)) - fs.Debugf(nil, "vfs metadata cache root is %q", root) + fs.Debugf(nil, "vfs cache: metadata root is %q", root) fcache, err := fscache.Get(root) if err != nil { @@ -315,7 +315,7 @@ func (c *Cache) Rename(name string, newName string, newObj fs.Object) (err error } c.mu.Unlock() - fs.Infof(name, "Renamed in cache to %q", newName) + fs.Infof(name, "vfs cache: renamed in cache to %q", newName) return nil } @@ -431,11 +431,11 @@ func (c *Cache) purgeEmptyDirs() { ctx := context.Background() err := operations.Rmdirs(ctx, c.fcache, "", true) if err != nil { - fs.Errorf(c.fcache, "Failed to remove empty directories from cache: %v", err) + fs.Errorf(c.fcache, "vfs cache: failed to remove empty directories from cache: %v", err) } err = operations.Rmdirs(ctx, c.fcacheMeta, "", true) if err != nil { - fs.Errorf(c.fcache, "Failed to remove empty directories from metadata cache: %v", err) + fs.Errorf(c.fcache, "vfs cache: failed to remove empty directories from metadata cache: %v", err) } } @@ -523,7 +523,7 @@ func (c *Cache) clean() { c.mu.Unlock() uploadsInProgress, uploadsQueued := c.writeback.Stats() - fs.Infof(nil, "Cleaned the cache: objects %d (was %d) in use %d, to upload %d, uploading %d, total size %v (was %v)", newItems, oldItems, totalInUse, uploadsQueued, uploadsInProgress, newUsed, oldUsed) + fs.Infof(nil, "vfs cache: cleaned: objects %d (was %d) in use %d, to upload %d, uploading %d, total size %v (was %v)", newItems, oldItems, totalInUse, uploadsQueued, uploadsInProgress, newUsed, oldUsed) } // cleaner calls clean at regular intervals @@ -531,7 +531,7 @@ func (c *Cache) clean() { // doesn't return until context is cancelled func (c *Cache) cleaner(ctx context.Context) { if c.opt.CachePollInterval <= 0 { - fs.Debugf(nil, "Cache cleaning thread disabled because poll interval <= 0") + fs.Debugf(nil, "vfs cache: cleaning thread disabled because poll interval <= 0") return } // Start cleaning the cache immediately @@ -544,7 +544,7 @@ func (c *Cache) cleaner(ctx context.Context) { case <-timer.C: c.clean() case <-ctx.Done(): - fs.Debugf(nil, "cache cleaner exiting") + fs.Debugf(nil, "vfs cache: cleaner exiting") return } } diff --git a/vfs/vfscache/downloaders/downloaders.go b/vfs/vfscache/downloaders/downloaders.go index 5c8967407..e5d3d3ce5 100644 --- a/vfs/vfscache/downloaders/downloaders.go +++ b/vfs/vfscache/downloaders/downloaders.go @@ -10,7 +10,6 @@ import ( "github.com/rclone/rclone/fs/accounting" "github.com/rclone/rclone/fs/asyncreader" "github.com/rclone/rclone/fs/chunkedreader" - "github.com/rclone/rclone/fs/log" "github.com/rclone/rclone/lib/ranges" "github.com/rclone/rclone/vfs/vfscommon" ) @@ -118,7 +117,7 @@ func New(item Item, opt *vfscommon.Options, remote string, src fs.Object) (dls * case <-ticker.C: err := dls.kickWaiters() if err != nil { - fs.Errorf(dls.src, "Failed to kick waiters: %v", err) + fs.Errorf(dls.src, "vfs cache: failed to kick waiters: %v", err) } case <-ctx.Done(): break @@ -140,7 +139,7 @@ func New(item Item, opt *vfscommon.Options, remote string, src fs.Object) (dls * func (dls *Downloaders) _countErrors(n int64, err error) { if err == nil && n != 0 { if dls.errorCount != 0 { - fs.Infof(dls.src, "Resetting error count to 0") + fs.Infof(dls.src, "vfs cache: downloader: resetting error count to 0") dls.errorCount = 0 dls.lastErr = nil } @@ -149,7 +148,7 @@ func (dls *Downloaders) _countErrors(n int64, err error) { if err != nil { dls.errorCount++ dls.lastErr = err - fs.Infof(dls.src, "Error count now %d: %v", dls.errorCount, err) + fs.Infof(dls.src, "vfs cache: downloader: error count now %d: %v", dls.errorCount, err) } } @@ -163,7 +162,7 @@ func (dls *Downloaders) countErrors(n int64, err error) { // // call with lock held func (dls *Downloaders) _newDownloader(r ranges.Range) (dl *downloader, err error) { - defer log.Trace(dls.src, "r=%v", r)("err=%v", &err) + // defer log.Trace(dls.src, "r=%v", r)("err=%v", &err) dl = &downloader{ kick: make(chan struct{}, 1), @@ -189,11 +188,11 @@ func (dls *Downloaders) _newDownloader(r ranges.Range) (dl *downloader, err erro _ = dl.close(err) dl.dls.countErrors(n, err) if err != nil { - fs.Errorf(dl.dls.src, "Failed to download: %v", err) + fs.Errorf(dl.dls.src, "vfs cache: failed to download: %v", err) } err = dl.dls.kickWaiters() if err != nil { - fs.Errorf(dl.dls.src, "Failed to kick waiters: %v", err) + fs.Errorf(dl.dls.src, "vfs cache: failed to kick waiters: %v", err) } }() @@ -238,7 +237,7 @@ func (dls *Downloaders) Close(inErr error) (err error) { // Download the range passed in returning when it has been downloaded // with an error from the downloading go routine. func (dls *Downloaders) Download(r ranges.Range) (err error) { - defer log.Trace(dls.src, "r=%+v", r)("err=%v", &err) + // defer log.Trace(dls.src, "r=%+v", r)("err=%v", &err) dls.mu.Lock() @@ -384,12 +383,12 @@ func (dls *Downloaders) kickWaiters() (err error) { err = dls._ensureDownloader(waiter.r) if err != nil { // Failures here will be retried by background kicker - fs.Errorf(dls.src, "Restart download failed: %v", err) + fs.Errorf(dls.src, "vfs cache: restart download failed: %v", err) } } if dls.errorCount > maxErrorCount { - fs.Errorf(dls.src, "Too many errors %d/%d: last error: %v", dls.errorCount, maxErrorCount, dls.lastErr) + fs.Errorf(dls.src, "vfs cache: too many errors %d/%d: last error: %v", dls.errorCount, maxErrorCount, dls.lastErr) dls._closeWaiters(dls.lastErr) return dls.lastErr } @@ -405,7 +404,7 @@ func (dls *Downloaders) kickWaiters() (err error) { // // Implementations must not retain p. func (dl *downloader) Write(p []byte) (n int, err error) { - defer log.Trace(dl.dls.src, "p_len=%d", len(p))("n=%d, err=%v", &n, &err) + // defer log.Trace(dl.dls.src, "p_len=%d", len(p))("n=%d, err=%v", &n, &err) // Kick the waiters on exit if some characters received defer func() { @@ -441,7 +440,7 @@ func (dl *downloader) Write(p []byte) (n int, err error) { // stop any future reading dl.mu.Lock() if !dl.stop { - fs.Debugf(dl.dls.src, "stopping download thread as it timed out") + fs.Debugf(dl.dls.src, "vfs cache: stopping download thread as it timed out") dl._stop() } } @@ -457,7 +456,7 @@ func (dl *downloader) Write(p []byte) (n int, err error) { // Kill this downloader if skipped too many bytes if !dl.stop && dl.skipped > maxSkipBytes { - fs.Debugf(dl.dls.src, "stopping download thread as it has skipped %d bytes", dl.skipped) + fs.Debugf(dl.dls.src, "vfs cache: stopping download thread as it has skipped %d bytes", dl.skipped) dl._stop() } @@ -475,7 +474,7 @@ func (dl *downloader) Write(p []byte) (n int, err error) { // // should be called on a fresh downloader func (dl *downloader) open(offset int64) (err error) { - defer log.Trace(dl.dls.src, "offset=%d", offset)("err=%v", &err) + // defer log.Trace(dl.dls.src, "offset=%d", offset)("err=%v", &err) dl.tr = accounting.Stats(dl.dls.ctx).NewTransfer(dl.dls.src) size := dl.dls.src.Size() @@ -508,7 +507,7 @@ func (dl *downloader) open(offset int64) (err error) { // close the downloader func (dl *downloader) close(inErr error) (err error) { - defer log.Trace(dl.dls.src, "inErr=%v", err)("err=%v", &err) + // defer log.Trace(dl.dls.src, "inErr=%v", err)("err=%v", &err) checkErr := func(e error) { if e == nil || errors.Cause(err) == asyncreader.ErrorStreamAbandoned { return @@ -540,7 +539,7 @@ func (dl *downloader) closed() bool { // // Call with the mutex held func (dl *downloader) _stop() { - defer log.Trace(dl.dls.src, "")("") + // defer log.Trace(dl.dls.src, "")("") // exit if have already called _stop if dl.stop { @@ -575,7 +574,7 @@ func (dl *downloader) stopAndClose(inErr error) (err error) { // Start downloading to the local file starting at offset until maxOffset. func (dl *downloader) download() (n int64, err error) { - defer log.Trace(dl.dls.src, "")("err=%v", &err) + // defer log.Trace(dl.dls.src, "")("err=%v", &err) n, err = dl.in.WriteTo(dl) if err != nil && errors.Cause(err) != asyncreader.ErrorStreamAbandoned { return n, errors.Wrap(err, "vfs reader: failed to write to cache file") diff --git a/vfs/vfscache/item.go b/vfs/vfscache/item.go index b7dbec428..835151ef6 100644 --- a/vfs/vfscache/item.go +++ b/vfs/vfscache/item.go @@ -11,7 +11,6 @@ import ( "github.com/pkg/errors" "github.com/rclone/rclone/fs" - "github.com/rclone/rclone/fs/log" "github.com/rclone/rclone/fs/operations" "github.com/rclone/rclone/lib/file" "github.com/rclone/rclone/lib/ranges" @@ -223,14 +222,14 @@ func (item *Item) _truncate(size int64) (err error) { osPath := item.c.toOSPath(item.name) // No locking in Cache fd, err = file.OpenFile(osPath, os.O_CREATE|os.O_WRONLY, 0600) if err != nil { - return errors.Wrap(err, "vfs item truncate: failed to open cache file") + return errors.Wrap(err, "vfs cache: truncate: failed to open cache file") } defer fs.CheckClose(fd, &err) err = file.SetSparse(fd) if err != nil { - fs.Debugf(item.name, "vfs item truncate: failed to set as a sparse file: %v", err) + fs.Debugf(item.name, "vfs cache: truncate: failed to set as a sparse file: %v", err) } } @@ -238,7 +237,7 @@ func (item *Item) _truncate(size int64) (err error) { err = fd.Truncate(size) if err != nil { - return errors.Wrap(err, "vfs truncate: failed to truncate") + return errors.Wrap(err, "vfs cache: truncate") } item.info.Size = size @@ -403,7 +402,7 @@ func (item *Item) IsDirty() bool { // Open the local file from the object passed in (which may be nil) // which implies we are about to create the file func (item *Item) Open(o fs.Object) (err error) { - defer log.Trace(o, "item=%p", item)("err=%v", &err) + // defer log.Trace(o, "item=%p", item)("err=%v", &err) item.mu.Lock() defer item.mu.Unlock() @@ -434,7 +433,7 @@ func (item *Item) Open(o fs.Object) (err error) { } err = file.SetSparse(fd) if err != nil { - fs.Debugf(item.name, "vfs cache item: failed to set as a sparse file: %v", err) + fs.Debugf(item.name, "vfs cache: failed to set as a sparse file: %v", err) } item.fd = fd @@ -479,7 +478,7 @@ func (item *Item) Open(o fs.Object) (err error) { // // Call with lock held func (item *Item) _store(ctx context.Context, storeFn StoreFn) (err error) { - defer log.Trace(item.name, "item=%p", item)("err=%v", &err) + // defer log.Trace(item.name, "item=%p", item)("err=%v", &err) // Transfer the temp file to the remote cacheObj, err := item.c.fcache.NewObject(ctx, item.name) @@ -503,10 +502,10 @@ func (item *Item) _store(ctx context.Context, storeFn StoreFn) (err error) { item.info.Dirty = false err = item._save() if err != nil { - fs.Errorf(item.name, "Failed to write metadata file: %v", err) + fs.Errorf(item.name, "vfs cache: failed to write metadata file: %v", err) } if storeFn != nil && item.o != nil { - fs.Debugf(item.name, "writeback object to VFS layer") + fs.Debugf(item.name, "vfs cache: writeback object to VFS layer") // Write the object back to the VFS layer as last // thing we do with mutex unlocked item.mu.Unlock() @@ -526,7 +525,7 @@ func (item *Item) store(ctx context.Context, storeFn StoreFn) (err error) { // Close the cache file func (item *Item) Close(storeFn StoreFn) (err error) { - defer log.Trace(item.o, "Item.Close")("err=%v", &err) + // defer log.Trace(item.o, "Item.Close")("err=%v", &err) var ( downloaders *downloaders.Downloaders syncWriteBack = item.c.opt.WriteBack <= 0 @@ -562,7 +561,7 @@ func (item *Item) Close(storeFn StoreFn) (err error) { // Accumulate and log errors checkErr := func(e error) { if e != nil { - fs.Errorf(item.o, "vfs cache item close failed: %v", e) + fs.Errorf(item.o, "vfs cache: item close failed: %v", e) if err == nil { err = e } @@ -608,7 +607,7 @@ func (item *Item) Close(storeFn StoreFn) (err error) { // upload the file to backing store if changed if item.info.Dirty { - fs.Debugf(item.name, "item changed - writeback in %v", item.c.opt.WriteBack) + fs.Infof(item.name, "vfs cache: queuing for upload in %v", item.c.opt.WriteBack) if syncWriteBack { // do synchronous writeback checkErr(item._store(context.Background(), storeFn)) @@ -806,13 +805,13 @@ func (item *Item) FindMissing(r ranges.Range) (outr ranges.Range) { // // call with the item lock held func (item *Item) _ensure(offset, size int64) (err error) { - defer log.Trace(item.name, "offset=%d, size=%d", offset, size)("err=%v", &err) + // defer log.Trace(item.name, "offset=%d, size=%d", offset, size)("err=%v", &err) if offset+size > item.info.Size { size = item.info.Size - offset } r := ranges.Range{Pos: offset, Size: size} present := item.info.Rs.Present(r) - fs.Debugf(nil, "looking for range=%+v in %+v - present %v", r, item.info.Rs, present) + fs.Debugf(nil, "vfs cache: looking for range=%+v in %+v - present %v", r, item.info.Rs, present) item.mu.Unlock() defer item.mu.Lock() if present { @@ -840,7 +839,7 @@ func (item *Item) _ensure(offset, size int64) (err error) { // // call with lock held func (item *Item) _written(offset, size int64) { - defer log.Trace(item.name, "offset=%d, size=%d", offset, size)("") + // defer log.Trace(item.name, "offset=%d, size=%d", offset, size)("") item.info.Rs.Insert(ranges.Range{Pos: offset, Size: size}) item.metaDirty = true } @@ -855,7 +854,7 @@ func (item *Item) _updateFingerprint() { oldFingerprint := item.info.Fingerprint item.info.Fingerprint = fs.Fingerprint(context.TODO(), item.o, false) if oldFingerprint != item.info.Fingerprint { - fs.Debugf(item.o, "fingerprint now %q", item.info.Fingerprint) + fs.Debugf(item.o, "vfs cache: fingerprint now %q", item.info.Fingerprint) item.metaDirty = true } } @@ -868,13 +867,13 @@ func (item *Item) _setModTime(modTime time.Time) { osPath := item.c.toOSPath(item.name) // No locking in Cache err := os.Chtimes(osPath, modTime, modTime) if err != nil { - fs.Errorf(item.name, "Failed to set modification time of cached file: %v", err) + fs.Errorf(item.name, "vfs cache: failed to set modification time of cached file: %v", err) } } // setModTime of the cache file and in the Item func (item *Item) setModTime(modTime time.Time) { - defer log.Trace(item.name, "modTime=%v", modTime)("") + // defer log.Trace(item.name, "modTime=%v", modTime)("") item.mu.Lock() item._updateFingerprint() item._setModTime(modTime) @@ -961,10 +960,10 @@ func (item *Item) WriteAtNoOverwrite(b []byte, off int64) (n int, skipped int, e ) // Write the range out ignoring already written chunks - fs.Debugf(item.name, "Ranges = %v", item.info.Rs) + // fs.Debugf(item.name, "Ranges = %v", item.info.Rs) for i := range foundRanges { foundRange := &foundRanges[i] - fs.Debugf(item.name, "foundRange[%d] = %v", i, foundRange) + // fs.Debugf(item.name, "foundRange[%d] = %v", i, foundRange) if foundRange.R.Pos != off { err = errors.New("internal error: offset of range is wrong") break @@ -972,12 +971,12 @@ func (item *Item) WriteAtNoOverwrite(b []byte, off int64) (n int, skipped int, e size := int(foundRange.R.Size) if foundRange.Present { // if present want to skip this range - fs.Debugf(item.name, "skip chunk offset=%d size=%d", off, size) + // fs.Debugf(item.name, "skip chunk offset=%d size=%d", off, size) nn = size skipped += size } else { // if range not present then we want to write it - fs.Debugf(item.name, "write chunk offset=%d size=%d", off, size) + // fs.Debugf(item.name, "write chunk offset=%d size=%d", off, size) nn, err = item.fd.WriteAt(b[:size], off) if err == nil && nn != size { err = errors.Errorf("downloader: short write: tried to write %d but only %d written", size, nn) diff --git a/vfs/vfscache/writeback/writeback.go b/vfs/vfscache/writeback/writeback.go index b4e4d9e85..59918e953 100644 --- a/vfs/vfscache/writeback/writeback.go +++ b/vfs/vfscache/writeback/writeback.go @@ -207,7 +207,7 @@ func (wb *WriteBack) _stopTimer() { return } wb.expiry = time.Time{} - fs.Debugf(nil, "resetTimer STOP") + // fs.Debugf(nil, "resetTimer STOP") if wb.timer != nil { wb.timer.Stop() wb.timer = nil @@ -228,7 +228,7 @@ func (wb *WriteBack) _resetTimer() { if dt < 0 { dt = 0 } - fs.Debugf(nil, "resetTimer dt=%v", dt) + // fs.Debugf(nil, "resetTimer dt=%v", dt) if wb.timer != nil { wb.timer.Stop() } @@ -330,13 +330,14 @@ func (wb *WriteBack) upload(ctx context.Context, wbItem *writeBackItem) { putFn := wbItem.putFn wbItem.tries++ + fs.Debugf(wbItem.name, "vfs cache: starting upload") + wb.mu.Unlock() err := putFn(ctx) wb.mu.Lock() wbItem.cancel() // cancel context to release resources since store done - //fs.Debugf(wbItem.name, "uploading = false %p item %p", wbItem, wbItem.item) wbItem.uploading = false wb.uploads-- @@ -347,7 +348,7 @@ func (wb *WriteBack) upload(ctx context.Context, wbItem *writeBackItem) { wbItem.delay = maxUploadDelay } if _, uerr := fserrors.Cause(err); uerr == context.Canceled { - fs.Infof(wbItem.name, "vfs cache: upload canceled sucessfully") + fs.Infof(wbItem.name, "vfs cache: upload canceled") // Upload was cancelled so reset timer wbItem.delay = wb.opt.WriteBack } else { @@ -372,7 +373,7 @@ func (wb *WriteBack) _cancelUpload(wbItem *writeBackItem) { if !wbItem.uploading { return } - fs.Infof(wbItem.name, "vfs cache: cancelling upload") + fs.Debugf(wbItem.name, "vfs cache: cancelling upload") if wbItem.cancel != nil { // Cancel the upload - this may or may not be effective wbItem.cancel() @@ -386,7 +387,7 @@ func (wb *WriteBack) _cancelUpload(wbItem *writeBackItem) { } // uploading items are not on the heap so add them back wb._pushItem(wbItem) - fs.Infof(wbItem.name, "vfs cache: cancelled upload") + fs.Debugf(wbItem.name, "vfs cache: cancelled upload") } // cancelUpload cancels the upload of the item if there is one in progress