Add more debugging logs to the mounting process so we get more visibility for customer issues (#130)

mount.go

@@ -17,6 +17,7 @@ package fuse
 import (
 	"context"
 	"fmt"
+	"log"
 	"net"
 	"os"
 	"os/exec"
@@ -53,11 +54,17 @@ func Mount(
 	}
 
 	// Begin the mounting process, which will continue in the background.
+	if config.DebugLogger != nil {
+		config.DebugLogger.Println("Beginning the mounting kickoff process")
+	}
 	ready := make(chan error, 1)
 	dev, err := mount(dir, config, ready)
 	if err != nil {
 		return nil, fmt.Errorf("mount: %v", err)
 	}
+	if config.DebugLogger != nil {
+		config.DebugLogger.Println("Completed the mounting kickoff process")
+	}
 
 	// Choose a parent context for ops.
 	cfgCopy := *config
@@ -65,6 +72,9 @@ func Mount(
 		cfgCopy.OpContext = context.Background()
 	}
 
+	if config.DebugLogger != nil {
+		config.DebugLogger.Println("Creating a connection object")
+	}
 	// Create a Connection object wrapping the device.
 	connection, err := newConnection(
 		cfgCopy,
@@ -74,6 +84,9 @@ func Mount(
 	if err != nil {
 		return nil, fmt.Errorf("newConnection: %v", err)
 	}
+	if config.DebugLogger != nil {
+		config.DebugLogger.Println("Successfully created the connection")
+	}
 
 	// Serve the connection in the background. When done, set the join status.
 	go func() {
@@ -82,6 +95,10 @@ func Mount(
 		close(mfs.joinStatusAvailable)
 	}()
 
+	if config.DebugLogger != nil {
+		config.DebugLogger.Println("Waiting for mounting process to complete")
+	}
+
 	// Wait for the mount process to complete.
 	if err := <-ready; err != nil {
 		return nil, fmt.Errorf("mount (background): %v", err)
@@ -110,13 +127,19 @@ func checkMountPoint(dir string) error {
 	return nil
 }
 
-func fusermount(binary string, argv []string, additionalEnv []string, wait bool) (*os.File, error) {
+func fusermount(binary string, argv []string, additionalEnv []string, wait bool, debugLogger *log.Logger) (*os.File, error) {
+	if debugLogger != nil {
+		debugLogger.Println("Creating a socket pair")
+	}
 	// Create a socket pair.
 	fds, err := syscall.Socketpair(syscall.AF_UNIX, syscall.SOCK_STREAM, 0)
 	if err != nil {
 		return nil, fmt.Errorf("Socketpair: %v", err)
 	}
 
+	if debugLogger != nil {
+		debugLogger.Println("Creating files to wrap the sockets")
+	}
 	// Wrap the sockets into os.File objects that we will pass off to fusermount.
 	writeFile := os.NewFile(uintptr(fds[0]), "fusermount-child-writes")
 	defer writeFile.Close()
@@ -124,6 +147,9 @@ func fusermount(binary string, argv []string, additionalEnv []string, wait bool)
 	readFile := os.NewFile(uintptr(fds[1]), "fusermount-parent-reads")
 	defer readFile.Close()
 
+	if debugLogger != nil {
+		debugLogger.Println("Starting fusermount/os mount")
+	}
 	// Start fusermount/mount_macfuse/mount_osxfuse.
 	cmd := exec.Command(binary, argv...)
 	cmd.Env = append(os.Environ(), "_FUSE_COMMFD=3")
@@ -141,6 +167,9 @@ func fusermount(binary string, argv []string, additionalEnv []string, wait bool)
 		return nil, fmt.Errorf("running %v: %v", binary, err)
 	}
 
+	if debugLogger != nil {
+		debugLogger.Println("Wrapping socket pair in a connection")
+	}
 	// Wrap the socket file in a connection.
 	c, err := net.FileConn(readFile)
 	if err != nil {
@@ -148,12 +177,18 @@ func fusermount(binary string, argv []string, additionalEnv []string, wait bool)
 	}
 	defer c.Close()
 
+	if debugLogger != nil {
+		debugLogger.Println("Checking that we have a unix domain socket")
+	}
 	// We expect to have a Unix domain socket.
 	uc, ok := c.(*net.UnixConn)
 	if !ok {
 		return nil, fmt.Errorf("Expected UnixConn, got %T", c)
 	}
 
+	if debugLogger != nil {
+		debugLogger.Println("Read a message from socket")
+	}
 	// Read a message.
 	buf := make([]byte, 32) // expect 1 byte
 	oob := make([]byte, 32) // expect 24 bytes
@@ -175,6 +210,10 @@ func fusermount(binary string, argv []string, additionalEnv []string, wait bool)
 
 	scm := scms[0]
 
+	if debugLogger != nil {
+		debugLogger.Println("Successfully read the socket message.")
+	}
+
 	// Pull out the FD returned by fusermount
 	gotFds, err := syscall.ParseUnixRights(&scm)
 	if err != nil {
@@ -185,6 +224,9 @@ func fusermount(binary string, argv []string, additionalEnv []string, wait bool)
 		return nil, fmt.Errorf("wanted 1 fd; got %#v", gotFds)
 	}
 
+	if debugLogger != nil {
+		debugLogger.Println("Converting FD into os.File")
+	}
 	// Turn the FD into an os.File.
 	return os.NewFile(uintptr(gotFds[0]), "/dev/fuse"), nil
 }

mount_darwin.go

@@ -205,7 +205,7 @@ func callMountCommFD(
 	env = append(env, "_FUSE_COMMVERS=2")
 	argv = append(argv, dir)
 
-	return fusermount(bin, argv, env, false)
+	return fusermount(bin, argv, env, false, cfg.DebugLogger)
 }
 
 // Begin the process of mounting at the given directory, returning a connection

mount_linux.go

@@ -55,6 +55,9 @@ var mountflagopts = map[string]func(uintptr) uintptr{
 var errFallback = errors.New("sentinel: fallback to fusermount(1)")
 
 func directmount(dir string, cfg *MountConfig) (*os.File, error) {
+	if cfg.DebugLogger != nil {
+		cfg.DebugLogger.Println("Preparing for direct mounting")
+	}
 	// We use syscall.Open + os.NewFile instead of os.OpenFile so that the file
 	// is opened in blocking mode. When opened in non-blocking mode, the Go
 	// runtime tries to use poll(2), which does not work with /dev/fuse.
@@ -63,6 +66,10 @@ func directmount(dir string, cfg *MountConfig) (*os.File, error) {
 		return nil, errFallback
 	}
 	dev := os.NewFile(uintptr(fd), "/dev/fuse")
+
+	if cfg.DebugLogger != nil {
+		cfg.DebugLogger.Println("Successfully opened the /dev/fuse in blocking mode")
+	}
 	// As per libfuse/fusermount.c:847: https://bit.ly/2SgtWYM#L847
 	data := fmt.Sprintf("fd=%d,rootmode=40000,user_id=%d,group_id=%d",
 		dev.Fd(), os.Getuid(), os.Getgid())
@@ -84,6 +91,10 @@ func directmount(dir string, cfg *MountConfig) (*os.File, error) {
 	}
 	delete(opts, "subtype")
 	data += "," + mapToOptionsString(opts)
+
+	if cfg.DebugLogger != nil {
+		cfg.DebugLogger.Println("Starting the unix mounting")
+	}
 	if err := unix.Mount(
 		cfg.FSName, // source
 		dir,        // target
@@ -97,6 +108,9 @@ func directmount(dir string, cfg *MountConfig) (*os.File, error) {
 		}
 		return nil, err
 	}
+	if cfg.DebugLogger != nil {
+		cfg.DebugLogger.Println("Unix mounting completed successfully")
+	}
 	return dev, nil
 }
 
@@ -108,6 +122,9 @@ func mount(dir string, cfg *MountConfig, ready chan<- error) (*os.File, error) {
 	// On linux, mounting is never delayed.
 	ready <- nil
 
+	if cfg.DebugLogger != nil {
+		cfg.DebugLogger.Println("Parsing fuse file descriptor")
+	}
 	// If the mountpoint is /dev/fd/N, assume that the file descriptor N is an
 	// already open FUSE channel. Parse it, cast it to an fd, and don't do any
 	// other part of the mount dance.
@@ -120,6 +137,9 @@ func mount(dir string, cfg *MountConfig, ready chan<- error) (*os.File, error) {
 	// have the CAP_SYS_ADMIN capability.
 	dev, err := directmount(dir, cfg)
 	if err == errFallback {
+		if cfg.DebugLogger != nil {
+			cfg.DebugLogger.Println("Directmount failed. Trying fallback.")
+		}
 		fusermountPath, err := findFusermount()
 		if err != nil {
 			return nil, err
@@ -129,7 +149,7 @@ func mount(dir string, cfg *MountConfig, ready chan<- error) (*os.File, error) {
 			"--",
 			dir,
 		}
-		return fusermount(fusermountPath, argv, []string{}, true)
+		return fusermount(fusermountPath, argv, []string{}, true, cfg.DebugLogger)
 	}
 	return dev, err
 }