Obtain file:line info in Connection.log.

connection.go

@@ -15,7 +15,10 @@
 package fuse
 
 import (
+	"fmt"
 	"log"
+	"path"
+	"runtime"
 	"sync"
 
 	"github.com/jacobsa/bazilfuse"
@@ -43,13 +46,32 @@ func newConnection(
 	return
 }
 
-// Log information for an operation with the given unique ID.
+// Log information for an operation with the given unique ID. calldepth is the
+// depth to use when recovering file:line information with runtime.Caller.
 func (c *Connection) log(
 	opID uint64,
+	calldepth int,
 	format string,
 	v ...interface{}) {
-	// TODO(jacobsa): Add op ID and fixed-width file:line to output.
-	c.logger.Printf(format, v...)
+	// 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(
+		"%v:%v] %v",
+		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
@@ -73,24 +95,24 @@ func (c *Connection) ReadOp() (op fuseops.Op, err error) {
 		c.nextOpID++
 
 		// Log the receipt of the operation.
-		c.log(opID, "Received: %v", bfReq)
+		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.log(opID, "Responding OK to Statfs.")
+			c.log(opID, 1, "Responding OK to Statfs.")
 			statfsReq.Respond(&bazilfuse.StatfsResponse{})
 			continue
 		}
 
 		// Convert it, if possible.
-		logForOp := func(format string, v ...interface{}) {
-			c.log(opID, format, v)
+		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, "Returning ENOSYS for unknown bazilfuse request: %v", bfReq)
+			c.log(opID, 1, "Returning ENOSYS for unknown bazilfuse request: %v", bfReq)
 			bfReq.RespondError(ENOSYS)
 			continue
 		}

debug.go

@@ -41,7 +41,7 @@ func initLogger() {
 		writer = os.Stderr
 	}
 
-	const flags = log.Ldate | log.Ltime | log.Lmicroseconds | log.Lshortfile
+	const flags = log.Ldate | log.Ltime | log.Lmicroseconds
 	gLogger = log.New(writer, "fuse: ", flags)
 }
 

fuseops/convert.go

@@ -33,7 +33,7 @@ import (
 // be called by anyone else.
 func Convert(
 	r bazilfuse.Request,
-	logForOp func(string, ...interface{}),
+	logForOp func(int, string, ...interface{}),
 	opsInFlight *sync.WaitGroup) (o Op) {
 	var co *commonOp
 
@@ -270,14 +270,14 @@ type commonOp struct {
 	opType      string
 	ctx         context.Context
 	r           bazilfuse.Request
-	log         func(string, ...interface{})
+	log         func(int, string, ...interface{})
 	opsInFlight *sync.WaitGroup
 }
 
 func (o *commonOp) init(
 	opType string,
 	r bazilfuse.Request,
-	log func(string, ...interface{}),
+	log func(int, string, ...interface{}),
 	opsInFlight *sync.WaitGroup) {
 	o.opType = opType
 	o.ctx = context.Background()
@@ -299,7 +299,8 @@ func (o *commonOp) Context() context.Context {
 }
 
 func (o *commonOp) Logf(format string, v ...interface{}) {
-	o.log(format, v...)
+	const calldepth = 2
+	o.log(calldepth, format, v...)
 }
 
 func (o *commonOp) respondErr(err error) {
@@ -307,7 +308,7 @@ func (o *commonOp) respondErr(err error) {
 		panic("Expect non-nil here.")
 	}
 
-	o.log(
+	o.Logf(
 		"Responding with error to %s: %v",
 		o.opType,
 		err)

fuseops/ops.go

@@ -107,7 +107,7 @@ func (o *InitOp) Respond(err error) {
 	resp.MaxReadahead = o.maxReadahead
 
 	// Respond.
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.InitRequest).Respond(&resp)
 }
 
@@ -152,7 +152,7 @@ func (o *LookUpInodeOp) Respond(err error) {
 	resp := bazilfuse.LookupResponse{}
 	convertChildInodeEntry(&o.Entry, &resp)
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.LookupRequest).Respond(&resp)
 }
 
@@ -186,7 +186,7 @@ func (o *GetInodeAttributesOp) Respond(err error) {
 		AttrValid: convertExpirationTime(o.AttributesExpiration),
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.GetattrRequest).Respond(&resp)
 }
 
@@ -226,7 +226,7 @@ func (o *SetInodeAttributesOp) Respond(err error) {
 		AttrValid: convertExpirationTime(o.AttributesExpiration),
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.SetattrRequest).Respond(&resp)
 }
 
@@ -287,7 +287,7 @@ func (o *ForgetInodeOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to ForgetInodeOp")
+	o.Logf("Responding OK to ForgetInodeOp")
 	o.r.(*bazilfuse.ForgetRequest).Respond()
 }
 
@@ -330,7 +330,7 @@ func (o *MkDirOp) Respond(err error) {
 	resp := bazilfuse.MkdirResponse{}
 	convertChildInodeEntry(&o.Entry, &resp.LookupResponse)
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.MkdirRequest).Respond(&resp)
 }
 
@@ -392,7 +392,7 @@ func (o *CreateFileOp) Respond(err error) {
 	}
 	convertChildInodeEntry(&o.Entry, &resp.LookupResponse)
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.CreateRequest).Respond(&resp)
 }
 
@@ -424,7 +424,7 @@ func (o *RmDirOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to RmDirOp")
+	o.Logf("Responding OK to RmDirOp")
 	o.r.(*bazilfuse.RemoveRequest).Respond()
 }
 
@@ -450,7 +450,7 @@ func (o *UnlinkOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to UnlinkOp")
+	o.Logf("Responding OK to UnlinkOp")
 	o.r.(*bazilfuse.RemoveRequest).Respond()
 }
 
@@ -496,7 +496,7 @@ func (o *OpenDirOp) Respond(err error) {
 		Handle: bazilfuse.HandleID(o.Handle),
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.OpenRequest).Respond(&resp)
 }
 
@@ -602,7 +602,7 @@ func (o *ReadDirOp) Respond(err error) {
 		Data: o.Data,
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.ReadRequest).Respond(&resp)
 }
 
@@ -631,7 +631,7 @@ func (o *ReleaseDirHandleOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to ReleaseDirHandleOp")
+	o.Logf("Responding OK to ReleaseDirHandleOp")
 	o.r.(*bazilfuse.ReleaseRequest).Respond()
 }
 
@@ -676,7 +676,7 @@ func (o *OpenFileOp) Respond(err error) {
 		Handle: bazilfuse.HandleID(o.Handle),
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.OpenRequest).Respond(&resp)
 }
 
@@ -721,7 +721,7 @@ func (o *ReadFileOp) Respond(err error) {
 		Data: o.Data,
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.ReadRequest).Respond(&resp)
 }
 
@@ -807,7 +807,7 @@ func (o *WriteFileOp) Respond(err error) {
 		Size: len(o.Data),
 	}
 
-	o.log("Responding: %v", &resp)
+	o.Logf("Responding: %v", &resp)
 	o.r.(*bazilfuse.WriteRequest).Respond(&resp)
 }
 
@@ -843,7 +843,7 @@ func (o *SyncFileOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to SyncFileOp")
+	o.Logf("Responding OK to SyncFileOp")
 	o.r.(*bazilfuse.FsyncRequest).Respond()
 }
 
@@ -910,7 +910,7 @@ func (o *FlushFileOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to FlushFileOp")
+	o.Logf("Responding OK to FlushFileOp")
 	o.r.(*bazilfuse.FlushRequest).Respond()
 }
 
@@ -939,6 +939,6 @@ func (o *ReleaseFileHandleOp) Respond(err error) {
 		return
 	}
 
-	o.log("Responding OK to ReleaseFileHandleOp")
+	o.Logf("Responding OK to ReleaseFileHandleOp")
 	o.r.(*bazilfuse.ReleaseRequest).Respond()
 }