fix: ignore hash on requests for encrypted virtual folder

lib/blockstorage/gocloud_url_storage.go

@@ -12,6 +12,7 @@ import (
 	"io"
 	"log"
 
+	"github.com/syncthing/syncthing/lib/hashutil"
 	"gocloud.dev/blob"
 	"gocloud.dev/gcerrors"
 
@@ -54,7 +55,7 @@ func NewGoCloudUrlStorage(ctx context.Context, url string) *GoCloudUrlStorage {
 }
 
 func getBlockStringKey(hash []byte) string {
-	return BlockDataSubFolder + "/" + hashToStringMapKey(hash)
+	return BlockDataSubFolder + "/" + hashutil.HashToStringMapKey(hash)
 }
 
 func getMetadataStringKey(name string) string {

lib/blockstorage/simple_ram_block_storage.go

@@ -6,11 +6,7 @@
 
 package blockstorage
 
-import "encoding/hex"
-
-func hashToStringMapKey(hash []byte) string {
-	return hex.EncodeToString(hash)
-}
+import "github.com/syncthing/syncthing/lib/hashutil"
 
 type HashedBlockMapInMemory struct {
 	blockMap map[string][]byte
@@ -23,14 +19,14 @@ func NewHashedBlockMapInMemory() *HashedBlockMapInMemory {
 }
 
 func (hm *HashedBlockMapInMemory) Get(hash []byte) (data []byte, ok bool) {
-	data, ok = hm.blockMap[hashToStringMapKey(hash)]
+	data, ok = hm.blockMap[hashutil.HashToStringMapKey(hash)]
 	return
 }
 
 func (hm *HashedBlockMapInMemory) Set(hash []byte, data []byte) {
-	hm.blockMap[hashToStringMapKey(hash)] = data
+	hm.blockMap[hashutil.HashToStringMapKey(hash)] = data
 }
 
 func (hm *HashedBlockMapInMemory) Delete(hash []byte) {
-	delete(hm.blockMap, hashToStringMapKey(hash))
+	delete(hm.blockMap, hashutil.HashToStringMapKey(hash))
 }

lib/hashutil/hashutil.go

@@ -0,0 +1,7 @@
+package hashutil
+
+import "encoding/hex"
+
+func HashToStringMapKey(hash []byte) string {
+	return hex.EncodeToString(hash)
+}

lib/model/folder_virtual.go

@@ -10,6 +10,7 @@ import (
 	"bytes"
 	"context"
 	"encoding/json"
+	"fmt"
 	"io"
 	"io/fs"
 	"log"
@@ -21,6 +22,7 @@ import (
 	"github.com/syncthing/syncthing/lib/config"
 	"github.com/syncthing/syncthing/lib/db"
 	"github.com/syncthing/syncthing/lib/events"
+	"github.com/syncthing/syncthing/lib/hashutil"
 	"github.com/syncthing/syncthing/lib/ignore"
 	"github.com/syncthing/syncthing/lib/logger"
 	"github.com/syncthing/syncthing/lib/protocol"
@@ -156,6 +158,7 @@ func (f *virtualFolderSyncthingService) Serve_backgroundDownloadTask() {
 				}
 
 				if !all_ok {
+					f.evLogger.Log(events.Failure, fmt.Sprintf("failed to pull all blocks for: %v", job))
 					return
 				}
 
@@ -219,7 +222,7 @@ func (f *virtualFolderSyncthingService) Serve(ctx context.Context) error {
 			return nil
 
 		case <-f.pullScheduled:
-			f.PullAll()
+			f.PullAllMissing()
 			continue
 		}
 	}
@@ -242,28 +245,80 @@ func (vf *virtualFolderSyncthingService) Scan(subs []string) error {
 	return vf.PullAll()
 }
 
-func (vf *virtualFolderSyncthingService) PullAll() error {
+func (vf *virtualFolderSyncthingService) PullAllMissing() error {
 	snap, err := vf.fset.Snapshot()
 	if err != nil {
 		return err
 	}
 	defer snap.Release()
 
+	vf.setState(FolderScanning)
+	defer vf.setState(FolderIdle)
+
 	snap.WithNeedTruncated(protocol.LocalDeviceID, func(f protocol.FileIntf) bool /* true to continue */ {
-		if f.IsDirectory() {
-			// no work to do for directories. directly take over:
-			fi, ok := snap.GetGlobal(f.FileName())
-			if ok {
-				vf.fset.UpdateOne(protocol.LocalDeviceID, &fi)
-			}
-		} else {
-			vf.RequestBackgroundDownload(f.FileName(), f.FileSize(), f.ModTime())
-		}
+		vf.PullOne(snap, f, true)
+		return true
+	})
+
+	return nil
+}
+
+func (vf *virtualFolderSyncthingService) PullAll() error {
+	snap, err := vf.fset.Snapshot()
+	if err != nil {
+		return err
+	}
+	defer snap.Release()
+
+	vf.setState(FolderScanning)
+	defer vf.setState(FolderIdle)
+
+	logger.DefaultLogger.Infof("pull all START")
+
+	snap.WithGlobalTruncated(func(f protocol.FileIntf) bool /* true to continue */ {
+		vf.PullOne(snap, f, true)
 		return true
 	})
 
+	logger.DefaultLogger.Infof("pull all END")
+
 	return nil
 }
+
+func (vf *virtualFolderSyncthingService) PullOne(snap *db.Snapshot, f protocol.FileIntf, synchronous bool) {
+	if f.IsDirectory() {
+		// no work to do for directories. directly take over:
+		fi, ok := snap.GetGlobal(f.FileName())
+		if ok {
+			vf.fset.UpdateOne(protocol.LocalDeviceID, &fi)
+		}
+	} else {
+		if !synchronous {
+			vf.RequestBackgroundDownload(f.FileName(), f.FileSize(), f.ModTime())
+		} else {
+			fi, ok := snap.GetGlobal(f.FileName())
+			if ok {
+				all_ok := true
+				for i, bi := range fi.Blocks {
+					logger.DefaultLogger.Infof("synchronous check block info #%v: %+v", i, bi, hashutil.HashToStringMapKey(bi.Hash))
+					_, ok := vf.GetBlockDataFromCacheOrDownload(snap, fi, bi)
+					all_ok = all_ok && ok
+					if !ok {
+						logger.DefaultLogger.Warnf("synchronous check block info FAILED. NOT OK: #%v: %+v", i, bi, hashutil.HashToStringMapKey(bi.Hash))
+					}
+				}
+
+				if all_ok {
+					logger.DefaultLogger.Infof("synchronous check block info (%v blocks, %v size) SUCCEEDED. ALL OK, file: %s", fi.Blocks, fi.Size, fi.Name)
+					vf.fset.UpdateOne(protocol.LocalDeviceID, &fi)
+				} else {
+					logger.DefaultLogger.Warnf("synchronous check block info FAILED. NOT ALL OK, file: %s", fi.Name)
+				}
+			}
+		}
+	}
+}
+
 func (f *virtualFolderSyncthingService) Errors() []FileError             { return []FileError{} }
 func (f *virtualFolderSyncthingService) WatchError() error               { return nil }
 func (f *virtualFolderSyncthingService) ScheduleForceRescan(path string) {}

lib/model/model.go

@@ -32,7 +32,9 @@ import (
 	"github.com/syncthing/syncthing/lib/db"
 	"github.com/syncthing/syncthing/lib/events"
 	"github.com/syncthing/syncthing/lib/fs"
+	"github.com/syncthing/syncthing/lib/hashutil"
 	"github.com/syncthing/syncthing/lib/ignore"
+	"github.com/syncthing/syncthing/lib/logger"
 	"github.com/syncthing/syncthing/lib/osutil"
 	"github.com/syncthing/syncthing/lib/protocol"
 	"github.com/syncthing/syncthing/lib/rand"
@@ -1579,17 +1581,21 @@ func (m *model) ccCheckEncryption(fcfg config.FolderConfiguration, folderDevice
 		// hasTokenRemote == true
 		ccToken = ccDeviceInfos.remote.EncryptionPasswordToken
 	}
+
+	logger.DefaultLogger.Infof("ccCheckEncryption() - check if token is already known. token: %v, folder-ID: %v", ccToken, fcfg.ID)
 	m.mut.RLock()
 	token, ok := m.folderEncryptionPasswordTokens[fcfg.ID]
 	m.mut.RUnlock()
 	if !ok {
+		logger.DefaultLogger.Infof("ccCheckEncryption() - token not yet set - try to read it from folder storage")
 		runner, ok := m.folderRunners.Get(fcfg.ID)
 		if !ok {
 			return errEncryptionPassword
 		}
 		var err error
 		token, err = runner.ReadEncryptionToken()
 		if err != nil && !fs.IsNotExist(err) {
+			logger.DefaultLogger.Infof("ccCheckEncryption() - Failure reading token. Abort")
 			if rerr, ok := redactPathError(err); ok {
 				return rerr
 			}
@@ -1598,12 +1604,16 @@ func (m *model) ccCheckEncryption(fcfg config.FolderConfiguration, folderDevice
 				redacted: errEncryptionTokenRead,
 			}
 		}
+
 		if err == nil {
+			logger.DefaultLogger.Infof("ccCheckEncryption() - read token successful")
 			m.mut.Lock()
 			m.folderEncryptionPasswordTokens[fcfg.ID] = token
 			m.mut.Unlock()
 		} else {
+			logger.DefaultLogger.Infof("ccCheckEncryption() - couldn't read token - will write it, assuming its first time")
 			if err := runner.WriteEncryptionToken(ccToken); err != nil {
+				logger.DefaultLogger.Infof("ccCheckEncryption() - write token failed! err: %v", err)
 				if rerr, ok := redactPathError(err); ok {
 					return rerr
 				} else {
@@ -1613,6 +1623,7 @@ func (m *model) ccCheckEncryption(fcfg config.FolderConfiguration, folderDevice
 					}
 				}
 			}
+			logger.DefaultLogger.Infof("ccCheckEncryption() - write token succeeded.")
 			m.mut.Lock()
 			m.folderEncryptionPasswordTokens[fcfg.ID] = ccToken
 			m.mut.Unlock()
@@ -2035,9 +2046,9 @@ func (m *model) Request(conn protocol.Connection, req *protocol.Request) (out pr
 	n := 0
 	virtualFolder, ok := folderRunner.(virtualFolderServiceI)
 	if ok {
-		if len(req.Hash) == 0 { // this happens for virtual encrypted folders
+		if true { // len(req.Hash) == 0 { // this happens for virtual encrypted folders, sometimes there is even a hash, but its invalid
 			l.Infof("%v REQ(in) get hash of req. block from virtual folder: %s - %s: %q / %q o=%d s=%d, blockNo=%v, hash=%v",
-				m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, req.Hash)
+				m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, hashutil.HashToStringMapKey(req.Hash))
 			// lookup hash:
 			folderFiles := m.folderFiles[req.Folder]
 			if folderFiles == nil {
@@ -2060,17 +2071,22 @@ func (m *model) Request(conn protocol.Connection, req *protocol.Request) (out pr
 		}
 		n, err = virtualFolder.GetHashBlockData(req.Hash, res.data)
 		l.Infof("%v REQ(in) get block from virtual folder: %s - %s: %q / %q o=%d s=%d, blockNo=%v, hash=%v",
-			m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, req.Hash)
+			m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, hashutil.HashToStringMapKey(req.Hash))
 	} else {
 		filesystemFolder, ok := folderRunner.(filesystemFolderServiceI)
 		if !ok {
 			l.Debugf("%v REQ(in) get block FAILED - unknown folder type. %s - %s: %q / %q o=%d s=%d, blockNo=%v, hash=%v",
-				m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, req.Hash)
+				m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, hashutil.HashToStringMapKey(req.Hash))
 			return nil, protocol.ErrGeneric
 		}
 
 		n, err = filesystemFolder.GetFileData(deviceID, req, res.data)
 	}
+	if err != nil {
+		l.Warnf("%v REQ(in) get block FAILED: %s - %s: %q / %q o=%d s=%d, blockNo=%v, hash=%v",
+			m, err, deviceID.Short(), req.Folder, req.Name, req.Offset, req.Size, req.BlockNo, hashutil.HashToStringMapKey(req.Hash))
+		return nil, err
+	}
 
 	if !folderCfg.Type.IsReceiveEncrypted() && len(req.Hash) > 0 && !scanner.Validate(res.data[:n], req.Hash, req.WeakHash) {
 		m.recheckFile(deviceID, req.Folder, req.Name, req.Offset, req.Hash, req.WeakHash)