debug: log inode number instead of encrypted filename

Makes the log output smaller and more readable.

4 files changed, 69 insertions, 15 deletions

diff --git a/cryptfs/cryptfs.go b/cryptfs/cryptfs.go
index 71ec996..46f5b65 100644
--- a/cryptfs/cryptfs.go
+++ b/cryptfs/cryptfs.go
@@ -58,6 +58,12 @@ func NewCryptFS(key []byte, useOpenssl bool) *CryptFS {
 	}
 }
 
+// Get plaintext block size
 func (be *CryptFS) PlainBS() uint64 {
 	return be.plainBS
 }
+
+// Get ciphertext block size
+func (be *CryptFS) CipherBS() uint64 {
+	return be.cipherBS
+}
diff --git a/cryptfs/cryptfs_content.go b/cryptfs/cryptfs_content.go
index e42011a..a4dc78a 100644
--- a/cryptfs/cryptfs_content.go
+++ b/cryptfs/cryptfs_content.go
@@ -7,8 +7,22 @@ import (
 	"os"
 	"errors"
 	"crypto/cipher"
+	"crypto/md5"
+	"encoding/hex"
 )
 
+const (
+	// A block of 4124 zero bytes has this md5
+	ZeroBlockMd5 = "64331af89bd15a987b39855338336237"
+)
+
+// md5sum - debug helper, return md5 hex string
+func md5sum(buf []byte) string {
+	rawHash := md5.Sum(buf)
+	hash := hex.EncodeToString(rawHash[:])
+	return hash
+}
+
 type CryptFile struct {
 	file *os.File
 	gcm cipher.AEAD
@@ -55,6 +69,7 @@ func (be *CryptFS) DecryptBlock(ciphertext []byte) ([]byte, error) {
 
 	// Extract nonce
 	nonce := ciphertext[:NONCE_LEN]
+	ciphertextOrig := ciphertext
 	ciphertext = ciphertext[NONCE_LEN:]
 
 	// Decrypt
@@ -63,7 +78,7 @@ func (be *CryptFS) DecryptBlock(ciphertext []byte) ([]byte, error) {
 	plaintext, err := be.gcm.Open(plaintext, nonce, ciphertext, nil)
 
 	if err != nil {
-		Warn.Printf("DecryptBlock: %s\n", err.Error())
+		Warn.Printf("DecryptBlock: %s, len=%d, md5=%s\n", err.Error(), len(ciphertextOrig), Warn.Md5sum(ciphertextOrig))
 		return nil, err
 	}
 
diff --git a/cryptfs/log.go b/cryptfs/log.go
index d40aa3f..850ec9e 100644
--- a/cryptfs/log.go
+++ b/cryptfs/log.go
@@ -15,6 +15,12 @@ func (l *logChannel) Printf(format string, args ...interface{}) {
 	}
 }
 
+func (l *logChannel) Println(s string) {
+	if l.enabled == true {
+		fmt.Println(s)
+	}
+}
+
 func (l *logChannel) Dump(d []byte) {
 	s := string(d)
 	fmt.Println(strings.Replace(s, "\000", "\\0", -1))
@@ -24,6 +30,14 @@ func (l *logChannel) Enable() {
 	l.enabled = true
 }
 
+// Only actually calculate the md5sum if the log channel is enabled to save
+// CPU cycles
+func (l *logChannel) Md5sum(buf []byte) string {
+	if l.enabled == false {
+		return ""
+	}
+	return md5sum(buf)
+}
 
 var Debug = logChannel{false}
 var Notice = logChannel{true}
diff --git a/pathfs_frontend/file.go b/pathfs_frontend/file.go
index a4ed30b..de00a11 100644
--- a/pathfs_frontend/file.go
+++ b/pathfs_frontend/file.go
@@ -30,13 +30,20 @@ type file struct {
 
 	// Parent CryptFS
 	cfs *cryptfs.CryptFS
+
+	// Inode number
+	ino uint64
 }
 
 func NewFile(fd *os.File, writeOnly bool, cfs *cryptfs.CryptFS) nodefs.File {
+	var st syscall.Stat_t
+	syscall.Fstat(int(fd.Fd()), &st)
+
 	return &file{
 		fd: fd,
 		writeOnly: writeOnly,
 		cfs: cfs,
+		ino: st.Ino,
 	}
 }
 
@@ -51,11 +58,13 @@ func (f *file) String() string {
 	return fmt.Sprintf("cryptFile(%s)", f.fd.Name())
 }
 
-// doRead - returns "length" plaintext bytes from plaintext offset "offset".
-// Reads the corresponding ciphertext from disk, decryptfs it, returns the relevant
-// part.
+// doRead - returns "length" plaintext bytes from plaintext offset "off".
+// Arguments "length" and "off" do not have to be aligned.
 //
-// Called by Read(), for RMW in Write() and Truncate()
+// doRead reads the corresponding ciphertext blocks from disk, decryptfs them and
+// returns the requested part of the plaintext.
+//
+// Called by Read() and by Write() and Truncate() for RMW
 func (f *file) doRead(off uint64, length uint64) ([]byte, fuse.Status) {
 
 	// Read the backing ciphertext in one go
@@ -65,18 +74,25 @@ func (f *file) doRead(off uint64, length uint64) ([]byte, fuse.Status) {
 	f.lock.Lock()
 	n, err := f.fd.ReadAt(ciphertext, int64(alignedOffset))
 	f.lock.Unlock()
-	ciphertext = ciphertext[0:n]
 	if err != nil && err != io.EOF {
 		cryptfs.Warn.Printf("read: ReadAt: %s\n", err.Error())
 		return nil, fuse.ToStatus(err)
 	}
-	cryptfs.Debug.Printf("ReadAt offset=%d length=%d -> n=%d len=%d\n", alignedLength, alignedOffset, n, len(ciphertext))
+	// Truncate ciphertext buffer down to actually read bytes
+	ciphertext = ciphertext[0:n]
+	{
+		blockNo := alignedOffset / f.cfs.CipherBS()
+		cryptfs.Debug.Printf("ReadAt offset=%d bytes (%d blocks), want=%d, got=%d\n", alignedOffset, blockNo, alignedLength, n)
+	}
 
 	// Decrypt it
 	plaintext, err := f.cfs.DecryptBlocks(ciphertext)
 	if err != nil {
-		cryptfs.Warn.Printf("Corrupt block at offset=%d\n", off + uint64(len(plaintext)))
-		cryptfs.Warn.Printf("doRead: returning IO error\n")
+		blockNo := (alignedOffset + uint64(len(plaintext))) / f.cfs.PlainBS()
+		cipherOff := blockNo * f.cfs.CipherBS()
+		plainOff := blockNo * f.cfs.PlainBS()
+		cryptfs.Warn.Printf("ino%d: doRead: corrupt block #%d (plainOff=%d/%d, cipherOff=%d/%d)\n",
+			f.ino, blockNo, plainOff, f.cfs.PlainBS(), cipherOff, f.cfs.CipherBS())
 		return nil, fuse.EIO
 	}
 
@@ -97,29 +113,29 @@ func (f *file) doRead(off uint64, length uint64) ([]byte, fuse.Status) {
 
 // Read - FUSE call
 func (f *file) Read(buf []byte, off int64) (resultData fuse.ReadResult, code fuse.Status) {
-	cryptfs.Debug.Printf("Read %s: offset=%d length=%d\n", f.fd.Name(), len(buf), off)
+	cryptfs.Debug.Printf("ino%d: Read: offset=%d length=%d\n", f.ino, len(buf), off)
 
 	if f.writeOnly {
-		cryptfs.Warn.Printf("Tried to read from write-only file\n")
+		cryptfs.Warn.Printf("ino%d: Tried to read from write-only file\n", f.ino)
 		return nil, fuse.EBADF
 	}
 
 	out, status := f.doRead(uint64(off), uint64(len(buf)))
 
 	if status == fuse.EIO {
-		cryptfs.Warn.Printf("Read failed with EIO: file %s, offset=%d, length=%d\n", f.fd.Name(), len(buf), off)
+		cryptfs.Warn.Printf("ino%d: Read failed with EIO, offset=%d, length=%d\n", f.ino, len(buf), off)
 	}
 	if status != fuse.OK {
 		return nil, status
 	}
 
-	cryptfs.Debug.Printf("Read: status %v, returning %d bytes\n", status, len(out))
+	cryptfs.Debug.Printf("ino%d: Read: status %v, returning %d bytes\n", f.ino, status, len(out))
 	return fuse.ReadResultData(out), status
 }
 
 // Write - FUSE call
 func (f *file) Write(data []byte, off int64) (uint32, fuse.Status) {
-	cryptfs.Debug.Printf("Write %s: offset=%d length=%d\n", f.fd.Name(), off, len(data))
+	cryptfs.Debug.Printf("ino%d: Write %s: offset=%d length=%d\n", f.ino, off, len(data))
 
 	var written uint32
 	status := fuse.OK
@@ -146,7 +162,10 @@ func (f *file) Write(data []byte, off int64) (uint32, fuse.Status) {
 		// Write
 		blockOffset, _ := b.CiphertextRange()
 		blockData = f.cfs.EncryptBlock(blockData)
-		cryptfs.Debug.Printf("WriteAt offset=%d length=%d\n", blockOffset, len(blockData))
+		cryptfs.Debug.Printf("ino%d: Writing %d bytes to block #%d, md5=%s\n", f.ino, len(blockData), b.BlockNo, cryptfs.Debug.Md5sum(blockData))
+		if len(blockData) != int(f.cfs.CipherBS()) {
+			cryptfs.Debug.Printf("ino%d: Writing partial block #%d (%d bytes)\n", b.BlockNo, len(blockData))
+		}
 		f.lock.Lock()
 		_, err := f.fd.WriteAt(blockData, int64(blockOffset))
 		f.lock.Unlock()