Replace Debug function with a Debugger interface to permit trace recording.

debug.go

@@ -9,13 +9,30 @@ func stack() string {
 	return string(buf[:runtime.Stack(buf, false)])
 }
 
-func nop(msg interface{}) {}
-
-// Debug is called to output debug messages, including protocol
-// traces. The default behavior is to do nothing.
+// Debug is used to output debug messages and protocol traces. The
+// default behaviour is to do nothing.
 //
 // The messages have human-friendly string representations and are
 // safe to marshal to JSON.
 //
 // Implementations must not retain msg.
-var Debug func(msg interface{}) = nop
+type Debugger interface {
+	// Begin begins a trace span, returns a key to close that span.
+	Begin(msg interface{}) interface{}
+
+	// End ends a trace span.
+	End(key, msg interface{})
+
+	// Print outputs a message not from a span.
+	Print(msg interface{})
+}
+
+type nopDebugger struct{}
+
+func (nopDebugger) Begin(msg interface{}) interface{} {
+	return nil
+}
+func (nopDebugger) End(key, msg interface{}) {}
+func (nopDebugger) Print(msg interface{}) {}
+
+var Debug Debugger = nopDebugger{}

fs/fstestutil/debug.go

@@ -18,28 +18,37 @@ func (f *flagDebug) IsBoolFlag() bool {
 	return true
 }
 
-func nop(msg interface{}) {}
-
 func (f *flagDebug) Set(s string) error {
 	v, err := strconv.ParseBool(s)
 	if err != nil {
 		return err
 	}
 	*f = flagDebug(v)
-	if v {
-		fuse.Debug = logMsg
-	} else {
-		fuse.Debug = nop
-	}
+	fuse.Debug = testDebugger{}
 	return nil
 }
 
 func (f *flagDebug) String() string {
 	return strconv.FormatBool(bool(*f))
 }
 
-func logMsg(msg interface{}) {
-	log.Printf("FUSE: %s\n", msg)
+// testDebugger is the Debugger used for tests, controlled
+// by the debug flag.
+type testDebugger struct {}
+
+func (d testDebugger) Print(msg interface{}) {
+	if debug {
+		log.Printf("FUSE: %s\n", msg)
+	}
+}
+
+func (d testDebugger) Begin(msg interface{}) interface{} {
+	d.Print(msg)
+	return nil
+}
+
+func (d testDebugger) End(span, msg interface{}) {
+	d.Print(msg)
 }
 
 func init() {

fs/fstestutil/mounted.go

@@ -103,11 +103,7 @@ func Mounted(srv *fs.Server, options ...fuse.MountOption) (*Mount, error) {
 func MountedT(t testing.TB, filesys fs.FS, options ...fuse.MountOption) (*Mount, error) {
 	srv := &fs.Server{
 		FS: filesys,
-	}
-	if debug {
-		srv.Debug = func(msg interface{}) {
-			t.Logf("FUSE: %s", msg)
-		}
+		Debug: testDebugger{},
 	}
 	return Mounted(srv, options...)
 }

fs/serve.go

@@ -289,12 +289,12 @@ type HandleReleaser interface {
 type Server struct {
 	FS FS
 
-	// Function to send debug log messages to. If nil, use fuse.Debug.
-	// Note that changing this or fuse.Debug may not affect existing
-	// calls to Serve.
+	// Debugger to use for log and trace information.
+	// If nil, use fuse.Debug. Note that changing this or fuse.Debug may not
+	// affect existingcalls to Serve.
 	//
-	// See fuse.Debug for the rules that log functions must follow.
-	Debug func(msg interface{})
+	// See fuse.Debugger for the expected interface.
+	Debug fuse.Debugger
 }
 
 // Serve serves the FUSE connection by making calls to the methods
@@ -355,7 +355,7 @@ type serveConn struct {
 	freeNode     []fuse.NodeID
 	freeHandle   []fuse.HandleID
 	nodeGen      uint64
-	debug        func(msg interface{})
+	debug        fuse.Debugger
 	dynamicInode func(parent uint64, name string) uint64
 }
 
@@ -474,15 +474,15 @@ func (c *serveConn) dropNode(id fuse.NodeID, n uint64) (forget bool) {
 		// this should only happen if refcounts kernel<->us disagree
 		// *and* two ForgetRequests for the same node race each other;
 		// this indicates a bug somewhere
-		c.debug(nodeRefcountDropBug{N: n, Node: id})
+		c.debug.Print(nodeRefcountDropBug{N: n, Node: id})
 
 		// we may end up triggering Forget twice, but that's better
 		// than not even once, and that's the best we can do
 		return true
 	}
 
 	if n > snode.refs {
-		c.debug(nodeRefcountDropBug{N: n, Refs: snode.refs, Node: id})
+		c.debug.Print(nodeRefcountDropBug{N: n, Refs: snode.refs, Node: id})
 		n = snode.refs
 	}
 
@@ -523,7 +523,7 @@ func (c *serveConn) getHandle(id fuse.HandleID) (shandle *serveHandle) {
 		shandle = c.handle[uint(id)]
 	}
 	if shandle == nil {
-		c.debug(missingHandle{
+		c.debug.Print(missingHandle{
 			Handle:    id,
 			MaxHandle: fuse.HandleID(len(c.handle)),
 		})
@@ -624,7 +624,7 @@ func (c *serveConn) serve(r fuse.Request) {
 
 	req := &serveRequest{Request: r, cancel: cancel}
 
-	c.debug(request{
+	span := c.debug.Begin(request{
 		Op:      opName(r),
 		Request: r.Hdr(),
 		In:      r,
@@ -639,7 +639,7 @@ func (c *serveConn) serve(r fuse.Request) {
 		}
 		if snode == nil {
 			c.meta.Unlock()
-			c.debug(response{
+			c.debug.End(span, response{
 				Op:      opName(r),
 				Request: logResponseHeader{ID: hdr.ID},
 				Error:   fuse.ESTALE.ErrnoName(),
@@ -690,7 +690,7 @@ func (c *serveConn) serve(r fuse.Request) {
 		} else {
 			msg.Out = resp
 		}
-		c.debug(msg)
+		c.debug.End(span, msg)
 
 		c.meta.Lock()
 		delete(c.req, hdr.ID)
@@ -817,7 +817,7 @@ func (c *serveConn) serve(r fuse.Request) {
 		}
 		c.meta.Unlock()
 		if oldNode == nil {
-			c.debug(logLinkRequestOldNodeNotFound{
+			c.debug.Print(logLinkRequestOldNodeNotFound{
 				Request: r.Hdr(),
 				In:      r,
 			})
@@ -1175,7 +1175,7 @@ func (c *serveConn) serve(r fuse.Request) {
 		}
 		c.meta.Unlock()
 		if newDirNode == nil {
-			c.debug(renameNewDirNodeNotFound{
+			c.debug.Print(renameNewDirNodeNotFound{
 				Request: r.Hdr(),
 				In:      r,
 			})

fuse.go

@@ -496,7 +496,7 @@ loop:
 	var req Request
 	switch m.hdr.Opcode {
 	default:
-		Debug(noOpcode{Opcode: m.hdr.Opcode})
+		Debug.Print(noOpcode{Opcode: m.hdr.Opcode})
 		goto unrecognized
 
 	case opLookup:
@@ -885,7 +885,7 @@ loop:
 	return req, nil
 
 corrupt:
-	Debug(malformedMessage{})
+	Debug.Print(malformedMessage{})
 	putMessage(m)
 	return nil, fmt.Errorf("fuse: malformed message")
 
@@ -922,7 +922,7 @@ func (c *Conn) respond(out *outHeader, n uintptr) {
 	msg := (*[1 << 30]byte)(unsafe.Pointer(out))[:n]
 	nn, err := syscall.Write(c.fd(), msg)
 	if nn != len(msg) || err != nil {
-		Debug(bugShortKernelWrite{
+		Debug.Print(bugShortKernelWrite{
 			Written: int64(nn),
 			Length:  int64(len(msg)),
 			Error:   errorString(err),