From f4c97492463b63b515c2eaf261ef14a9863b75ef Mon Sep 17 00:00:00 2001
From: Jarek Kowalski <jaak@jkowalski.net>
Date: Mon, 12 Mar 2018 16:49:45 -0700
Subject: [PATCH] additional logging for hash cache

---
 internal/hashcache/hashcache_reader.go | 11 +++++++++++
 snapshot/upload.go                     |  7 +++++++
 2 files changed, 18 insertions(+)

diff --git a/internal/hashcache/hashcache_reader.go b/internal/hashcache/hashcache_reader.go
index 2a83f6df0..3ae186844 100644
--- a/internal/hashcache/hashcache_reader.go
+++ b/internal/hashcache/hashcache_reader.go
@@ -5,6 +5,7 @@
 	"io"
 
 	"github.com/kopia/kopia/internal/jsonstream"
+	"github.com/rs/zerolog/log"
 )
 
 // Reader supports reading a stream of hash cache entries.
@@ -25,6 +26,7 @@ type reader struct {
 // FindEntry looks for an entry with a given name in hash cache stream and returns it or nil if not found.
 func (hcr *reader) FindEntry(relativeName string) *Entry {
 	for hcr.nextEntry != nil && isLess(hcr.nextEntry.Name, relativeName) {
+		log.Debug().Msgf("skipping %v while looking for %v", hcr.nextEntry.Name, relativeName)
 		hcr.readahead()
 	}
 
@@ -35,6 +37,12 @@ func (hcr *reader) FindEntry(relativeName string) *Entry {
 		return e
 	}
 
+	if hcr.nextEntry == nil {
+		log.Debug().Msgf("end of cache while looking for %v", relativeName)
+		return nil
+	}
+
+	log.Debug().Msgf("skipping %v while looking for %v", hcr.nextEntry.Name, relativeName)
 	return nil
 }
 
@@ -56,6 +64,8 @@ func (hcr *reader) readahead() {
 		*e = Entry{}
 		if err := hcr.reader.Read(e); err == nil {
 			hcr.nextEntry = e
+		} else if err != io.EOF {
+			log.Debug().Msgf("unable to read next hash cache entry: %v", err)
 		}
 	}
 
@@ -99,5 +109,6 @@ func Open(r io.Reader) Reader {
 	hcr.nextEntry = nil
 	hcr.first = true
 	hcr.readahead()
+	log.Debug().Msgf("nextEntry: %v", hcr.nextEntry)
 	return &hcr
 }
diff --git a/snapshot/upload.go b/snapshot/upload.go
index 63ee0683c..ba65420a4 100644
--- a/snapshot/upload.go
+++ b/snapshot/upload.go
@@ -347,6 +347,8 @@ func uploadDirInternal(
 			// Avoid hashing by reusing previous object ID.
 			de, hash, err = newDirEntry(e, cachedEntry.ObjectID), cachedEntry.Hash, nil
 		} else {
+			log.Debug().Msgf("hash cache miss for %v", entryRelativePath)
+
 			switch entry := entry.(type) {
 			case fs.Symlink:
 				de, hash, err = u.uploadSymlinkInternal(entry, entryRelativePath)
@@ -430,8 +432,13 @@ func (u *Uploader) Upload(
 	u.cacheReader = hashcache.Open(nil)
 	u.stats = Stats{}
 	if old != nil {
+		log.Debug().Msgf("opening hash cache: %v", old.HashCacheID)
 		if r, err := u.repo.Objects.Open(old.HashCacheID); err == nil {
 			u.cacheReader = hashcache.Open(r)
+			log.Debug().Msgf("opened hash cache: %v", old.HashCacheID)
+		} else {
+			log.Warn().Msgf("unable to open hash cache %v: %v", old.HashCacheID, err)
+
 		}
 	}