Added a facility for per-op logging using --fuse.debug.

The output contains an op ID, to make it easier to distinguish parallel
operations.

connection.go

@@ -15,7 +15,10 @@
 package fuse
 
 import (
+	"fmt"
 	"log"
+	"path"
+	"runtime"
 	"sync"
 
 	"github.com/jacobsa/bazilfuse"
@@ -27,6 +30,9 @@ type Connection struct {
 	logger      *log.Logger
 	wrapped     *bazilfuse.Conn
 	opsInFlight sync.WaitGroup
+
+	// For logging purposes only.
+	nextOpID uint32
 }
 
 // Responsibility for closing the wrapped connection is transferred to the
@@ -42,6 +48,35 @@ func newConnection(
 	return
 }
 
+// Log information for an operation with the given ID. calldepth is the depth
+// to use when recovering file:line information with runtime.Caller.
+func (c *Connection) log(
+	opID uint32,
+	calldepth int,
+	format string,
+	v ...interface{}) {
+	// Get file:line info.
+	var file string
+	var line int
+	var ok bool
+
+	_, file, line, ok = runtime.Caller(calldepth)
+	if !ok {
+		file = "???"
+	}
+
+	// Format the actual message to be printed.
+	msg := fmt.Sprintf(
+		"Op 0x%08x %v:%v] %v",
+		opID,
+		path.Base(file),
+		line,
+		fmt.Sprintf(format, v...))
+
+	// Print it.
+	c.logger.Println(msg)
+}
+
 // Read the next op from the kernel process. Return io.EOF if the kernel has
 // closed the connection.
 //
@@ -58,20 +93,29 @@ func (c *Connection) ReadOp() (op fuseops.Op, err error) {
 			return
 		}
 
-		c.logger.Printf("Received: %v", bfReq)
+		// Choose an ID for this operation.
+		opID := c.nextOpID
+		c.nextOpID++
+
+		// Log the receipt of the operation.
+		c.log(opID, 1, "Received: %v", bfReq)
 
 		// Special case: responding to this is required to make mounting work on OS
 		// X. We don't currently expose the capability for the file system to
 		// intercept this.
 		if statfsReq, ok := bfReq.(*bazilfuse.StatfsRequest); ok {
-			c.logger.Println("Responding OK to Statfs.")
+			c.log(opID, 1, "Responding OK to Statfs.")
 			statfsReq.Respond(&bazilfuse.StatfsResponse{})
 			continue
 		}
 
 		// Convert it, if possible.
-		if op = fuseops.Convert(bfReq, c.logger, &c.opsInFlight); op == nil {
-			c.logger.Printf("Returning ENOSYS for unknown bazilfuse request: %v", bfReq)
+		logForOp := func(calldepth int, format string, v ...interface{}) {
+			c.log(opID, calldepth+1, format, v)
+		}
+
+		if op = fuseops.Convert(bfReq, logForOp, &c.opsInFlight); op == nil {
+			c.log(opID, 1, "Returning ENOSYS for unknown bazilfuse request: %v", bfReq)
 			bfReq.RespondError(ENOSYS)
 			continue
 		}

debug.go

@@ -20,6 +20,7 @@ import (
 	"io/ioutil"
 	"log"
 	"os"
+	"sync"
 )
 
 var fEnableDebug = flag.Bool(
@@ -27,13 +28,24 @@ var fEnableDebug = flag.Bool(
 	false,
 	"Write FUSE debugging messages to stderr.")
 
-// Create a logger based on command-line flag settings.
-func getLogger() *log.Logger {
+var gLogger *log.Logger
+var gLoggerOnce sync.Once
+
+func initLogger() {
+	if !flag.Parsed() {
+		panic("initLogger called before flags available.")
+	}
+
 	var writer io.Writer = ioutil.Discard
 	if *fEnableDebug {
 		writer = os.Stderr
 	}
 
-	const flags = log.Ldate | log.Ltime | log.Lmicroseconds | log.Lshortfile
-	return log.New(writer, "fuse: ", flags)
+	const flags = log.Ldate | log.Ltime | log.Lmicroseconds
+	gLogger = log.New(writer, "", flags)
+}
+
+func getLogger() *log.Logger {
+	gLoggerOnce.Do(initLogger)
+	return gLogger
 }

fuseops/convert.go

@@ -18,7 +18,6 @@
 package fuseops
 
 import (
-	"log"
 	"reflect"
 	"sync"
 	"time"
@@ -34,7 +33,7 @@ import (
 // be called by anyone else.
 func Convert(
 	r bazilfuse.Request,
-	logger *log.Logger,
+	logForOp func(int, string, ...interface{}),
 	opsInFlight *sync.WaitGroup) (o Op) {
 	var co *commonOp
 
@@ -218,7 +217,7 @@ func Convert(
 		return
 	}
 
-	co.init(reflect.TypeOf(o).String(), r, logger, opsInFlight)
+	co.init(reflect.TypeOf(o).String(), r, logForOp, opsInFlight)
 	return
 }
 
@@ -271,19 +270,19 @@ type commonOp struct {
 	opType      string
 	ctx         context.Context
 	r           bazilfuse.Request
-	logger      *log.Logger
+	log         func(int, string, ...interface{})
 	opsInFlight *sync.WaitGroup
 }
 
 func (o *commonOp) init(
 	opType string,
 	r bazilfuse.Request,
-	logger *log.Logger,
+	log func(int, string, ...interface{}),
 	opsInFlight *sync.WaitGroup) {
 	o.opType = opType
 	o.ctx = context.Background()
 	o.r = r
-	o.logger = logger
+	o.log = log
 	o.opsInFlight = opsInFlight
 }
 
@@ -299,12 +298,17 @@ func (o *commonOp) Context() context.Context {
 	return o.ctx
 }
 
+func (o *commonOp) Logf(format string, v ...interface{}) {
+	const calldepth = 2
+	o.log(calldepth, format, v...)
+}
+
 func (o *commonOp) respondErr(err error) {
 	if err == nil {
 		panic("Expect non-nil here.")
 	}
 
-	o.logger.Printf(
+	o.Logf(
 		"Responding with error to %s: %v",
 		o.opType,
 		err)

fuseops/ops.go

@@ -38,6 +38,11 @@ type Op interface {
 	// Repond to the operation with the supplied error. If there is no error, set
 	// any necessary output fields and then call Respond(nil).
 	Respond(error)
+
+	// Log information tied to this operation, with semantics equivalent to
+	// log.Printf, except that the format is different and logging is suppressed
+	// if --fuse.debug is not set.
+	Logf(format string, v ...interface{})
 }
 
 ////////////////////////////////////////////////////////////////////////
@@ -102,7 +107,7 @@ func (o *InitOp) Respond(err error) {
 	resp.MaxReadahead = o.maxReadahead
 
 	// Respond.
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.InitRequest).Respond(&resp)
 }
 
@@ -147,7 +152,7 @@ func (o *LookUpInodeOp) Respond(err error) {
 	resp := bazilfuse.LookupResponse{}
 	convertChildInodeEntry(&o.Entry, &resp)
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.LookupRequest).Respond(&resp)
 }
 
@@ -181,7 +186,7 @@ func (o *GetInodeAttributesOp) Respond(err error) {
 		AttrValid: convertExpirationTime(o.AttributesExpiration),
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.GetattrRequest).Respond(&resp)
 }
 
@@ -221,7 +226,7 @@ func (o *SetInodeAttributesOp) Respond(err error) {
 		AttrValid: convertExpirationTime(o.AttributesExpiration),
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.SetattrRequest).Respond(&resp)
 }
 
@@ -282,7 +287,7 @@ func (o *ForgetInodeOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to ForgetInodeOp")
+	o.Logf("Responding OK to ForgetInodeOp")
 	o.r.(*bazilfuse.ForgetRequest).Respond()
 }
 
@@ -325,7 +330,7 @@ func (o *MkDirOp) Respond(err error) {
 	resp := bazilfuse.MkdirResponse{}
 	convertChildInodeEntry(&o.Entry, &resp.LookupResponse)
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.MkdirRequest).Respond(&resp)
 }
 
@@ -387,7 +392,7 @@ func (o *CreateFileOp) Respond(err error) {
 	}
 	convertChildInodeEntry(&o.Entry, &resp.LookupResponse)
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.CreateRequest).Respond(&resp)
 }
 
@@ -419,7 +424,7 @@ func (o *RmDirOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to RmDirOp")
+	o.Logf("Responding OK to RmDirOp")
 	o.r.(*bazilfuse.RemoveRequest).Respond()
 }
 
@@ -445,7 +450,7 @@ func (o *UnlinkOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to UnlinkOp")
+	o.Logf("Responding OK to UnlinkOp")
 	o.r.(*bazilfuse.RemoveRequest).Respond()
 }
 
@@ -491,7 +496,7 @@ func (o *OpenDirOp) Respond(err error) {
 		Handle: bazilfuse.HandleID(o.Handle),
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.OpenRequest).Respond(&resp)
 }
 
@@ -597,7 +602,7 @@ func (o *ReadDirOp) Respond(err error) {
 		Data: o.Data,
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.ReadRequest).Respond(&resp)
 }
 
@@ -626,7 +631,7 @@ func (o *ReleaseDirHandleOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to ReleaseDirHandleOp")
+	o.Logf("Responding OK to ReleaseDirHandleOp")
 	o.r.(*bazilfuse.ReleaseRequest).Respond()
 }
 
@@ -671,7 +676,7 @@ func (o *OpenFileOp) Respond(err error) {
 		Handle: bazilfuse.HandleID(o.Handle),
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.OpenRequest).Respond(&resp)
 }
 
@@ -716,7 +721,7 @@ func (o *ReadFileOp) Respond(err error) {
 		Data: o.Data,
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.ReadRequest).Respond(&resp)
 }
 
@@ -802,7 +807,7 @@ func (o *WriteFileOp) Respond(err error) {
 		Size: len(o.Data),
 	}
 
-	o.commonOp.logger.Printf("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.WriteRequest).Respond(&resp)
 }
 
@@ -838,7 +843,7 @@ func (o *SyncFileOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to SyncFileOp")
+	o.Logf("Responding OK to SyncFileOp")
 	o.r.(*bazilfuse.FsyncRequest).Respond()
 }
 
@@ -905,7 +910,7 @@ func (o *FlushFileOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to FlushFileOp")
+	o.Logf("Responding OK to FlushFileOp")
 	o.r.(*bazilfuse.FlushRequest).Respond()
 }
 
@@ -934,6 +939,6 @@ func (o *ReleaseFileHandleOp) Respond(err error) {
 		return
 	}
 
-	o.commonOp.logger.Printf("Responding OK to ReleaseFileHandleOp")
+	o.Logf("Responding OK to ReleaseFileHandleOp")
 	o.r.(*bazilfuse.ReleaseRequest).Respond()
 }