diff --git a/connection.go b/connection.go index fb34af4..1f92678 100644 --- a/connection.go +++ b/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 } diff --git a/debug.go b/debug.go index b1ba48a..af8a224 100644 --- a/debug.go +++ b/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) } diff --git a/fuseops/convert.go b/fuseops/convert.go index 81ea71f..3c3b5f9 100644 --- a/fuseops/convert.go +++ b/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) diff --git a/fuseops/ops.go b/fuseops/ops.go index 8c9f405..0d84442 100644 --- a/fuseops/ops.go +++ b/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() }