fsck: clean up log output

Make sure we get only 1 warning output per
problem.

Also, add new corruption types to broken_fs_v1.4.

8 files changed, 37 insertions, 42 deletions

diff --git a/internal/contentenc/content.go b/internal/contentenc/content.go
index c4ba7c9..76b486d 100644
--- a/internal/contentenc/content.go
+++ b/internal/contentenc/content.go
@@ -186,7 +186,7 @@ func (be *ContentEnc) DecryptBlock(ciphertext []byte, blockNo uint64, fileID []b
 	plaintext, err := be.cryptoCore.AEADCipher.Open(plaintext, nonce, ciphertext, aData)
 
 	if err != nil {
-		tlog.Warn.Printf("DecryptBlock: %s, len=%d", err.Error(), len(ciphertextOrig))
+		tlog.Debug.Printf("DecryptBlock: %s, len=%d", err.Error(), len(ciphertextOrig))
 		tlog.Debug.Println(hex.Dump(ciphertextOrig))
 		if be.forceDecode && err == stupidgcm.ErrAuth {
 			return plaintext, err
diff --git a/internal/contentenc/file_header.go b/internal/contentenc/file_header.go
index 5e638ff..62d24cb 100644
--- a/internal/contentenc/file_header.go
+++ b/internal/contentenc/file_header.go
@@ -7,11 +7,10 @@ package contentenc
 import (
 	"bytes"
 	"encoding/binary"
+	"fmt"
 	"log"
-	"syscall"
 
 	"github.com/rfjakob/gocryptfs/internal/cryptocore"
-	"github.com/rfjakob/gocryptfs/internal/tlog"
 )
 
 const (
@@ -48,19 +47,16 @@ var allZeroFileID = make([]byte, headerIDLen)
 // ParseHeader - parse "buf" into fileHeader object
 func ParseHeader(buf []byte) (*FileHeader, error) {
 	if len(buf) != HeaderLen {
-		tlog.Warn.Printf("ParseHeader: invalid length: want %d bytes, got %d. Returning EINVAL.", HeaderLen, len(buf))
-		return nil, syscall.EINVAL
+		return nil, fmt.Errorf("ParseHeader: invalid length, want=%d have=%d", HeaderLen, len(buf))
 	}
 	var h FileHeader
 	h.Version = binary.BigEndian.Uint16(buf[0:headerVersionLen])
 	if h.Version != CurrentVersion {
-		tlog.Warn.Printf("ParseHeader: invalid version: want %d, got %d. Returning EINVAL.", CurrentVersion, h.Version)
-		return nil, syscall.EINVAL
+		return nil, fmt.Errorf("ParseHeader: invalid version, want=%d have=%d", CurrentVersion, h.Version)
 	}
 	h.ID = buf[headerVersionLen:]
 	if bytes.Equal(h.ID, allZeroFileID) {
-		tlog.Warn.Printf("ParseHeader: file id is all-zero. Returning EINVAL.")
-		return nil, syscall.EINVAL
+		return nil, fmt.Errorf("ParseHeader: file id is all-zero")
 	}
 	return &h, nil
 }
diff --git a/internal/ctlsock/ctlsock_serve.go b/internal/ctlsock/ctlsock_serve.go
index 0fd0993..4b02948 100644
--- a/internal/ctlsock/ctlsock_serve.go
+++ b/internal/ctlsock/ctlsock_serve.go
@@ -167,6 +167,8 @@ func sendResponse(conn *net.UnixConn, err error, result string, warnText string)
 			if se, ok := pe.Err.(syscall.Errno); ok {
 				msg.ErrNo = int32(se)
 			}
+		} else if err == syscall.ENOENT {
+			msg.ErrNo = int32(syscall.ENOENT)
 		}
 	}
 	jsonMsg, err := json.Marshal(msg)
diff --git a/internal/fusefrontend/file.go b/internal/fusefrontend/file.go
index e1ce6a9..af13170 100644
--- a/internal/fusefrontend/file.go
+++ b/internal/fusefrontend/file.go
@@ -97,7 +97,7 @@ func (f *file) readFileID() ([]byte, error) {
 	n, err := f.fd.ReadAt(buf, 0)
 	if err != nil {
 		if err == io.EOF && n != 0 {
-			tlog.Warn.Printf("ino%d: readFileID: incomplete file, got %d instead of %d bytes",
+			tlog.Warn.Printf("readFileID %d: incomplete file, got %d instead of %d bytes",
 				f.qIno.Ino, n, readLen)
 		}
 		return nil, err
@@ -156,7 +156,8 @@ func (f *file) doRead(dst []byte, off uint64, length uint64) ([]byte, fuse.Statu
 		}
 		if err != nil {
 			f.fileTableEntry.HeaderLock.Unlock()
-			return nil, fuse.ToStatus(err)
+			tlog.Warn.Printf("doRead %d: corrupt header: %v", f.qIno.Ino, err)
+			return nil, fuse.EIO
 		}
 		f.fileTableEntry.ID = tmpID
 		// Downgrade the lock.
@@ -200,11 +201,11 @@ func (f *file) doRead(dst []byte, off uint64, length uint64) ([]byte, fuse.Statu
 		if f.fs.args.ForceDecode && err == stupidgcm.ErrAuth {
 			// We do not have the information which block was corrupt here anymore,
 			// but DecryptBlocks() has already logged it anyway.
-			tlog.Warn.Printf("ino%d: doRead off=%d len=%d: returning corrupt data due to forcedecode",
+			tlog.Warn.Printf("doRead %d: off=%d len=%d: returning corrupt data due to forcedecode",
 				f.qIno.Ino, off, length)
 		} else {
 			curruptBlockNo := firstBlockNo + f.contentEnc.PlainOffToBlockNo(uint64(len(plaintext)))
-			tlog.Warn.Printf("ino%d: doRead: corrupt block #%d: %v", f.qIno.Ino, curruptBlockNo, err)
+			tlog.Warn.Printf("doRead %d: corrupt block #%d: %v", f.qIno.Ino, curruptBlockNo, err)
 			return nil, fuse.EIO
 		}
 	}
@@ -233,29 +234,20 @@ func (f *file) Read(buf []byte, off int64) (resultData fuse.ReadResult, code fus
 		tlog.Warn.Printf("Read: rejecting oversized request with EMSGSIZE, len=%d", len(buf))
 		return nil, fuse.Status(syscall.EMSGSIZE)
 	}
-
 	f.fdLock.RLock()
 	defer f.fdLock.RUnlock()
 
 	tlog.Debug.Printf("ino%d: FUSE Read: offset=%d length=%d", f.qIno.Ino, len(buf), off)
-
 	if f.fs.args.SerializeReads {
 		serialize_reads.Wait(off, len(buf))
 	}
-
 	out, status := f.doRead(buf[:0], uint64(off), uint64(len(buf)))
-
 	if f.fs.args.SerializeReads {
 		serialize_reads.Done()
 	}
-
-	if status == fuse.EIO {
-		tlog.Warn.Printf("ino%d: Read: returning EIO, offset=%d, length=%d", f.qIno.Ino, len(buf), off)
-	}
 	if status != fuse.OK {
 		return nil, status
 	}
-
 	tlog.Debug.Printf("ino%d: Read: status %v, returning %d bytes", f.qIno.Ino, status, len(out))
 	return fuse.ReadResultData(out), status
 }
diff --git a/internal/fusefrontend/fs.go b/internal/fusefrontend/fs.go
index e246264..5f84541 100644
--- a/internal/fusefrontend/fs.go
+++ b/internal/fusefrontend/fs.go
@@ -365,12 +365,13 @@ func (fs *FS) decryptSymlinkTarget(cData64 string) (string, error) {
 }
 
 // Readlink implements pathfs.Filesystem.
-func (fs *FS) Readlink(path string, context *fuse.Context) (out string, status fuse.Status) {
-	cPath, err := fs.getBackingPath(path)
+func (fs *FS) Readlink(relPath string, context *fuse.Context) (out string, status fuse.Status) {
+	cPath, err := fs.encryptPath(relPath)
 	if err != nil {
 		return "", fuse.ToStatus(err)
 	}
-	cTarget, err := os.Readlink(cPath)
+	cAbsPath := filepath.Join(fs.args.Cipherdir, cPath)
+	cTarget, err := os.Readlink(cAbsPath)
 	if err != nil {
 		return "", fuse.ToStatus(err)
 	}
@@ -380,7 +381,7 @@ func (fs *FS) Readlink(path string, context *fuse.Context) (out string, status f
 	// Symlinks are encrypted like file contents (GCM) and base64-encoded
 	target, err := fs.decryptSymlinkTarget(cTarget)
 	if err != nil {
-		tlog.Warn.Printf("Readlink: %v", err)
+		tlog.Warn.Printf("Readlink %q: decrypting target failed: %v", cPath, err)
 		return "", fuse.EIO
 	}
 	return string(target), fuse.OK
diff --git a/internal/fusefrontend/fs_dir.go b/internal/fusefrontend/fs_dir.go
index fcfdbb5..e13afed 100644
--- a/internal/fusefrontend/fs_dir.go
+++ b/internal/fusefrontend/fs_dir.go
@@ -286,12 +286,13 @@ func (fs *FS) OpenDir(dirName string, context *fuse.Context) ([]fuse.DirEntry, f
 			cachedIV, err = nametransform.ReadDirIV(cDirAbsPath)
 			if err != nil {
 				fs.dirIVLock.RUnlock()
-				// This can happen during normal operation when the directory has
-				// been deleted concurrently. But it can also mean that the
-				// gocryptfs.diriv is missing due to an error, so log the event
-				// at "info" level.
-				tlog.Info.Printf("OpenDir: %v", err)
-				return nil, fuse.ToStatus(err)
+				// The directory itself does not exist
+				if err == syscall.ENOENT {
+					return nil, fuse.ENOENT
+				}
+				// Any other problem warrants an error message
+				tlog.Warn.Printf("OpenDir %q: could not read gocryptfs.diriv: %v", cDirName, err)
+				return nil, fuse.EIO
 			}
 			fs.nameTransform.DirIVCache.Store(dirName, cachedIV, cDirName)
 			fs.dirIVLock.RUnlock()
diff --git a/internal/nametransform/diriv.go b/internal/nametransform/diriv.go
index 06f029e..10f3226 100644
--- a/internal/nametransform/diriv.go
+++ b/internal/nametransform/diriv.go
@@ -2,6 +2,7 @@ package nametransform
 
 import (
 	"bytes"
+	"fmt"
 	"io"
 	"log"
 	"os"
@@ -26,11 +27,16 @@ const (
 
 // ReadDirIV - read the "gocryptfs.diriv" file from "dir" (absolute ciphertext path)
 // This function is exported because it allows for an efficient readdir implementation.
+// If the directory itself cannot be opened, a syscall error will be returned.
+// Otherwise, a fmt.Errorf() error value is returned with the details.
 func ReadDirIV(dir string) (iv []byte, err error) {
 	fd, err := os.Open(filepath.Join(dir, DirIVFilename))
 	if err != nil {
 		// Note: getting errors here is normal because of concurrent deletes.
-		return nil, err
+		// Strip the useless annotation that os.Open has added and return
+		// the plain syscall error. The caller will log a nice message.
+		err2 := err.(*os.PathError)
+		return nil, err2.Err
 	}
 	defer fd.Close()
 	return fdReadDirIV(fd)
@@ -42,9 +48,7 @@ func ReadDirIVAt(dirfd *os.File) (iv []byte, err error) {
 	fdRaw, err := syscallcompat.Openat(int(dirfd.Fd()), DirIVFilename,
 		syscall.O_RDONLY|syscall.O_NOFOLLOW, 0)
 	if err != nil {
-		tlog.Warn.Printf("ReadDirIVAt: opening %q in dir %q failed: %v",
-			DirIVFilename, dirfd.Name(), err)
-		return nil, err
+		return nil, fmt.Errorf("openat failed: %v", err)
 	}
 	fd := os.NewFile(uintptr(fdRaw), DirIVFilename)
 	defer fd.Close()
@@ -61,17 +65,14 @@ func fdReadDirIV(fd *os.File) (iv []byte, err error) {
 	iv = make([]byte, DirIVLen+1)
 	n, err := fd.Read(iv)
 	if err != nil && err != io.EOF {
-		tlog.Warn.Printf("ReadDirIVAt: Read failed: %v", err)
-		return nil, err
+		return nil, fmt.Errorf("read failed: %v", err)
 	}
 	iv = iv[0:n]
 	if len(iv) != DirIVLen {
-		tlog.Warn.Printf("ReadDirIVAt: wanted %d bytes, got %d. Returning EINVAL.", DirIVLen, len(iv))
-		return nil, syscall.EINVAL
+		return nil, fmt.Errorf("wanted %d bytes, got %d", DirIVLen, len(iv))
 	}
 	if bytes.Equal(iv, allZeroDirIV) {
-		tlog.Warn.Printf("ReadDirIVAt: diriv is all-zero. Returning EINVAL.")
-		return nil, syscall.EINVAL
+		return nil, fmt.Errorf("diriv is all-zero")
 	}
 	return iv, nil
 }
diff --git a/internal/tlog/log.go b/internal/tlog/log.go
index f6c0acf..1c80911 100644
--- a/internal/tlog/log.go
+++ b/internal/tlog/log.go
@@ -110,6 +110,8 @@ func init() {
 	Warn = &toggledLogger{
 		Enabled: true,
 		Logger:  log.New(os.Stderr, "", 0),
+		prefix:  ColorYellow,
+		postfix: ColorReset,
 	}
 	Fatal = &toggledLogger{
 		Enabled: true,