From 66764ef74ddb66401c7c4415263420d039a48714 Mon Sep 17 00:00:00 2001 From: Geert Jansen Date: Sun, 23 Nov 2025 22:11:29 +0000 Subject: [PATCH 1/2] Add wire log A wire log captures information about each FUSE request, including name, duration and arguments. File system implementations can also add custom fields. Wire log are useful for understanding application access patterns and troubleshooting performance issues. Wire logs are serialized in JSON format and can e.g. be loaded and analyzed in a notebook environment. --- connection.go | 27 ++++- mount.go | 1 + mount_config.go | 5 + samples/wirelog/testfs.go | 154 ++++++++++++++++++++++++ samples/wirelog/wirelog_test.go | 201 ++++++++++++++++++++++++++++++++ wirelog.go | 107 +++++++++++++++++ 6 files changed, 494 insertions(+), 1 deletion(-) create mode 100644 samples/wirelog/testfs.go create mode 100644 samples/wirelog/wirelog_test.go create mode 100644 wirelog.go diff --git a/connection.go b/connection.go index 53dbb551..ee11399d 100644 --- a/connection.go +++ b/connection.go @@ -62,6 +62,7 @@ type Connection struct { cfg MountConfig debugLogger *log.Logger errorLogger *log.Logger + wireLogger io.Writer // The device through which we're talking to the kernel, and the protocol // version that we're using to talk to it. @@ -87,6 +88,17 @@ type opState struct { inMsg *buffer.InMessage outMsg *buffer.OutMessage op interface{} + wlog *WireLogRecord +} + +// Return the current wirelog record from the context, if any. +func GetWirelog(ctx context.Context) *WireLogRecord { + val := ctx.Value(contextKey) + state, ok := val.(opState) + if ok { + return state.wlog + } + return nil } // Create a connection wrapping the supplied file descriptor connected to the @@ -97,11 +109,13 @@ func newConnection( cfg MountConfig, debugLogger *log.Logger, errorLogger *log.Logger, + wireLogger io.Writer, dev *os.File) (*Connection, error) { c := &Connection{ cfg: cfg, debugLogger: debugLogger, errorLogger: errorLogger, + wireLogger: wireLogger, dev: dev, cancelFuncs: make(map[uint64]func()), } @@ -461,7 +475,11 @@ func (c *Connection) ReadOp() (_ context.Context, op interface{}, _ error) { // Set up a context that remembers information about this op. ctx := c.beginOp(inMsg.Header().Opcode, inMsg.Header().Unique) - ctx = context.WithValue(ctx, contextKey, opState{inMsg, outMsg, op}) + var wlog *WireLogRecord + if c.wireLogger != nil { + wlog = NewWireLogRecord() + } + ctx = context.WithValue(ctx, contextKey, opState{inMsg, outMsg, op, wlog}) // Return the op to the user. return ctx, op, nil @@ -573,6 +591,13 @@ func (c *Connection) Reply(ctx context.Context, opErr error) error { outMsg.Sglist = nil } + if c.wireLogger != nil { + entry, err := formatWireLogEntry(op, opErr, state.wlog) + if err == nil { + c.wireLogger.Write(entry) + } + } + return nil } diff --git a/mount.go b/mount.go index 20cd47af..23db0a8e 100644 --- a/mount.go +++ b/mount.go @@ -80,6 +80,7 @@ func Mount( cfgCopy, config.DebugLogger, config.ErrorLogger, + config.WireLogger, dev) if err != nil { return nil, fmt.Errorf("newConnection: %v", err) diff --git a/mount_config.go b/mount_config.go index e0e64470..f95895ad 100644 --- a/mount_config.go +++ b/mount_config.go @@ -17,6 +17,7 @@ package fuse import ( "context" "fmt" + "io" "log" "runtime" "strings" @@ -47,6 +48,10 @@ type MountConfig struct { // performed. DebugLogger *log.Logger + // A logger to use for logging fuse wire requests. If nil, no wire logging is + // performed. + WireLogger io.Writer + // Linux only. OS X always behaves as if writeback caching is disabled. // // By default on Linux we allow the kernel to perform writeback caching diff --git a/samples/wirelog/testfs.go b/samples/wirelog/testfs.go new file mode 100644 index 00000000..607043a5 --- /dev/null +++ b/samples/wirelog/testfs.go @@ -0,0 +1,154 @@ +// Copyright 2025 Google Inc. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package wirelog + +import ( + "context" + "io" + "os" + "strings" + + "github.com/jacobsa/fuse" + "github.com/jacobsa/fuse/fuseops" + "github.com/jacobsa/fuse/fuseutil" +) + +// NewTestFS returns a simple file system with a root directory and one file "foo". +func NewTestFS() fuse.Server { + return fuseutil.NewFileSystemServer(&testFS{}) +} + +type testFS struct { + fuseutil.NotImplementedFileSystem +} + +const ( + rootInode fuseops.InodeID = fuseops.RootInodeID + iota + fileInode +) + +var fileName string = "foo" +var fileContents string = "bar" +var fileMode os.FileMode = 0444 +var fileHandle fuseops.HandleID = 10 + +func (fs *testFS) LookUpInode( + ctx context.Context, + op *fuseops.LookUpInodeOp) error { + if wlog := fuse.GetWirelog(ctx); wlog != nil { + wlog.Extra["lookup"] = "yes" + } + if op.Parent == rootInode && op.Name == fileName { + op.Entry.Child = fileInode + op.Entry.Attributes = fuseops.InodeAttributes{ + Nlink: 1, + Mode: fileMode, + Size: uint64(len(fileContents)), + } + return nil + } + return fuse.ENOENT +} + +func (fs *testFS) GetInodeAttributes( + ctx context.Context, + op *fuseops.GetInodeAttributesOp) error { + switch op.Inode { + case rootInode: + op.Attributes = fuseops.InodeAttributes{ + Nlink: 1, + Mode: 0555 | os.ModeDir, + } + case fileInode: + op.Attributes = fuseops.InodeAttributes{ + Nlink: 1, + Mode: fileMode, + Size: uint64(len(fileContents)), + } + default: + return fuse.ENOENT + } + return nil +} + +func (fs *testFS) OpenDir( + ctx context.Context, + op *fuseops.OpenDirOp) error { + if op.Inode == rootInode { + return nil + } + return fuse.ENOENT +} + +func (fs *testFS) ReadDir( + ctx context.Context, + op *fuseops.ReadDirOp) error { + if op.Inode != rootInode { + return fuse.ENOENT + } + + entries := []fuseutil.Dirent{ + { + Offset: 1, + Inode: fileInode, + Name: fileName, + Type: fuseutil.DT_File, + }, + } + + if op.Offset > fuseops.DirOffset(len(entries)) { + return nil + } + + for _, e := range entries[op.Offset:] { + n := fuseutil.WriteDirent(op.Dst[op.BytesRead:], e) + if n == 0 { + break + } + op.BytesRead += n + } + return nil +} + +func (fs *testFS) OpenFile( + ctx context.Context, + op *fuseops.OpenFileOp) error { + if op.Inode == fileInode { + op.Handle = fileHandle + return nil + } + return fuse.ENOENT +} + +func (fs *testFS) FlushFile( + ctx context.Context, + op *fuseops.FlushFileOp) error { + return nil +} + +func (fs *testFS) ReadFile( + ctx context.Context, + op *fuseops.ReadFileOp) error { + if op.Inode != fileInode { + return fuse.ENOENT + } + reader := strings.NewReader(fileContents) + var err error + op.BytesRead, err = reader.ReadAt(op.Dst, op.Offset) + if err == io.EOF { + return nil + } + return err +} diff --git a/samples/wirelog/wirelog_test.go b/samples/wirelog/wirelog_test.go new file mode 100644 index 00000000..f5a8ffa5 --- /dev/null +++ b/samples/wirelog/wirelog_test.go @@ -0,0 +1,201 @@ +// Copyright 2025 Google Inc. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package wirelog + +import ( + "bytes" + "context" + "encoding/json" + "os" + "path" + "syscall" + "testing" + "time" + + "github.com/jacobsa/fuse" + "github.com/jacobsa/fuse/fuseops" + . "github.com/jacobsa/ogletest" +) + +func TestWireLog(t *testing.T) { RunTests(t) } + +type WireLogTest struct { + ctx context.Context + dir string + mfs *fuse.MountedFileSystem + buf bytes.Buffer +} + +func init() { RegisterTestSuite(&WireLogTest{}) } + +func (t *WireLogTest) SetUp(ti *TestInfo) { + t.ctx = ti.Ctx + var err error + t.dir, err = os.MkdirTemp("", "wirelog_test") + AssertEq(nil, err) + + // Mount the file system. + t.mfs, err = fuse.Mount(t.dir, NewTestFS(), &fuse.MountConfig{ + WireLogger: &t.buf, + OpContext: t.ctx, + }) + AssertEq(nil, err) +} + +func (t *WireLogTest) TearDown() { + // Ensure unmounted. + if t.mfs != nil { + fuse.Unmount(t.dir) + t.mfs.Join(t.ctx) + } + os.RemoveAll(t.dir) +} + +// Helper to load Args into a struct +func loadArgs(entry fuse.WireLogRecord, dst any) { + b, err := json.Marshal(entry.Args) + AssertEq(nil, err) + err = json.Unmarshal(b, dst) + AssertEq(nil, err) +} + +func (t *WireLogTest) RunWorkloadAndCheckLogs() { + // 1. Stat the file. + filePath := path.Join(t.dir, "foo") + fi, err := os.Stat(filePath) + AssertEq(nil, err) + ExpectEq(3, fi.Size()) + + // 2. Read the file. + content, err := os.ReadFile(filePath) + AssertEq(nil, err) + ExpectEq("bar", string(content)) + + // Unmount to ensure everything is flushed/closed. + err = fuse.Unmount(t.dir) + AssertEq(nil, err) + + // Wait for the connection to close. + err = t.mfs.Join(t.ctx) + AssertEq(nil, err) + + // Mark as joined so TearDown doesn't try again. + t.mfs = nil + + // Parse the logs. + ops := make(map[string][]fuse.WireLogRecord) + decoder := json.NewDecoder(&t.buf) + + for decoder.More() { + var entry fuse.WireLogRecord + err := decoder.Decode(&entry) + AssertEq(nil, err) + ExpectTrue(time.Now().After(entry.StartTime)) + ExpectGt(entry.Duration, 0) + ops[entry.Operation] = append(ops[entry.Operation], entry) + } + + // 1. initOp + entries, ok := ops["initOp"] + AssertTrue(ok) + AssertEq(1, len(entries)) + entry := entries[0] + AssertEq(0, entry.Status) + AssertEq(nil, entry.Context) + + // 2. LookUpInodeOp + entries, ok = ops["LookUpInodeOp"] + AssertTrue(ok) + ExpectGe(len(entries), 1) + entry = entries[0] + ExpectEq(entry.Status, 0) + AssertNe(nil, entry.Context) + AssertGt(entry.Context.FuseID, 0) + var lookupOp fuseops.LookUpInodeOp + loadArgs(entry, &lookupOp) + ExpectEq(fileName, lookupOp.Name) + ExpectEq(rootInode, lookupOp.Parent) + ExpectEq(fileInode, lookupOp.Entry.Child) + ExpectEq(1, lookupOp.Entry.Attributes.Nlink) + ExpectEq(len(fileContents), lookupOp.Entry.Attributes.Size) + ExpectEq(fileMode, lookupOp.Entry.Attributes.Mode) + ExpectEq("yes", entry.Extra["lookup"]) + + // 3. GetInodeAttributesOp + entries, ok = ops["GetInodeAttributesOp"] + AssertTrue(ok) + ExpectGe(len(entries), 2) + entry = entries[1] // first entry is the root dir + ExpectEq(0, entry.Status) + AssertNe(nil, entry.Context) + AssertGt(entry.Context.FuseID, 0) + var getattrOp fuseops.GetInodeAttributesOp + loadArgs(entry, &getattrOp) + ExpectEq(fileInode, getattrOp.Inode) + ExpectEq(1, getattrOp.Attributes.Nlink) + ExpectEq(len(fileContents), getattrOp.Attributes.Size) + ExpectEq(fileMode, getattrOp.Attributes.Mode) + + // 4. OpenFileOp + entries, ok = ops["OpenFileOp"] + AssertTrue(ok) + AssertEq(1, len(entries)) + entry = entries[0] + ExpectEq(0, entry.Status) + AssertNe(nil, entry.Context) + AssertGt(entry.Context.FuseID, 0) + var openOp fuseops.OpenFileOp + loadArgs(entry, &openOp) + ExpectEq(fileInode, openOp.Inode) + ExpectEq(fileHandle, openOp.Handle) + + // 5. ReadFileOp + entries, ok = ops["ReadFileOp"] + AssertTrue(ok) + AssertEq(1, len(entries)) + entry = entries[0] + ExpectEq(0, entry.Status) + AssertNe(nil, entry.Context) + AssertGt(entry.Context.FuseID, 0) + var readOp fuseops.ReadFileOp + loadArgs(entries[0], &readOp) + ExpectEq(fileInode, readOp.Inode) + ExpectEq(fileHandle, readOp.Handle) + ExpectEq(0, readOp.Offset) + ExpectGt(readOp.Size, 0) + ExpectEq(len(fileContents), readOp.BytesRead) + + // 6. FlushFileOp + entries, ok = ops["FlushFileOp"] + AssertTrue(ok) + AssertEq(1, len(entries)) + entry = entries[0] + ExpectEq(0, entry.Status) + AssertNe(nil, entry.Context) + AssertGt(entry.Context.FuseID, 0) + var flushOp fuseops.FlushFileOp + loadArgs(entry, &flushOp) + ExpectEq(fileInode, flushOp.Inode) + AssertEq(fileHandle, flushOp.Handle) + + // 7. ReleaseFileHandleOp + entries, ok = ops["ReleaseFileHandleOp"] + AssertTrue(ok) + AssertEq(1, len(entries)) + entry = entries[0] + ExpectEq(entry.Status, syscall.ENOSYS) + AssertNe(nil, entry.Context) + AssertGt(entry.Context.FuseID, 0) +} diff --git a/wirelog.go b/wirelog.go new file mode 100644 index 00000000..a67143cf --- /dev/null +++ b/wirelog.go @@ -0,0 +1,107 @@ +// Copyright 2025 Google Inc. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package fuse + +import ( + "encoding/json" + "errors" + "reflect" + "slices" + "syscall" + "time" + + "github.com/jacobsa/fuse/fuseops" +) + +func NewWireLogRecord() *WireLogRecord { + return &WireLogRecord{ + StartTime: time.Now(), + Args: make(map[string]any), + Extra: make(map[string]any), + } +} + +// WireLogRecord struct +type WireLogRecord struct { + Operation string + StartTime time.Time + Duration time.Duration + Status int + Context *fuseops.OpContext + Args map[string]any + Extra map[string]any // Custom fields added by file system implementation +} + +// Params that are ignored +var ignoredParams = []string{"OpContext", "Dst", "Data"} + +// Format a wire log entry +func formatWireLogEntry(op any, opErr error, wlog *WireLogRecord) ([]byte, error) { + v := reflect.ValueOf(op).Elem() + t := v.Type() + + // Operation name and duration + wlog.Operation = t.Name() + wlog.Duration = time.Since(wlog.StartTime) + + // Result of the operation + var errno syscall.Errno + if opErr == nil { + wlog.Status = 0 + } else if errors.As(opErr, &errno) { + wlog.Status = int(errno) + } + + // Separate section for the operation context + if f := v.FieldByName("OpContext"); f.IsValid() { + if ctx, ok := f.Interface().(fuseops.OpContext); ok { + wlog.Context = &ctx + } + } + + // Copy the the rest of the fields to the "Args" section + args := map[string]any{} + for i := 0; i < v.NumField(); i++ { + f := v.Field(i) + if f.Kind() == reflect.Ptr && f.IsNil() { + continue + } + if f.Kind() == reflect.Func { + continue + } + fieldName := t.Field(i).Name + if slices.Contains(ignoredParams, fieldName) { + continue + } + args[fieldName] = f.Interface() + } + + switch typed := op.(type) { + case *fuseops.ReadFileOp: + args["BytesRead"] = typed.BytesRead + + case *fuseops.WriteFileOp: + args["Size"] = len(typed.Data) + } + + wlog.Args = args + + // Serialize as pretty-printed JSON + buf, err := json.MarshalIndent(wlog, "", " ") + if err == nil { + buf = append(buf, '\n') + } + return buf, err +} From 6b5f0f8b4fd10485ce7164bf20d728446cb4c911 Mon Sep 17 00:00:00 2001 From: Geert Jansen Date: Tue, 25 Nov 2025 14:44:46 +0000 Subject: [PATCH 2/2] Address PR feedback --- connection.go | 3 ++- wirelog.go | 9 +++++---- 2 files changed, 7 insertions(+), 5 deletions(-) diff --git a/connection.go b/connection.go index ee11399d..ebb86b73 100644 --- a/connection.go +++ b/connection.go @@ -91,7 +91,8 @@ type opState struct { wlog *WireLogRecord } -// Return the current wirelog record from the context, if any. +// Return the current wirelog record from the context if the MountConfig +// contained a non-nil wireLogger, nil otherwise. func GetWirelog(ctx context.Context) *WireLogRecord { val := ctx.Value(contextKey) state, ok := val.(opState) diff --git a/wirelog.go b/wirelog.go index a67143cf..2ce7ab12 100644 --- a/wirelog.go +++ b/wirelog.go @@ -25,6 +25,7 @@ import ( "github.com/jacobsa/fuse/fuseops" ) +// NewWireLogRecord creates a new empty WireLogRecord. func NewWireLogRecord() *WireLogRecord { return &WireLogRecord{ StartTime: time.Now(), @@ -33,21 +34,21 @@ func NewWireLogRecord() *WireLogRecord { } } -// WireLogRecord struct +// A WireLogRecord is created for each FUSE operation when WireLogger is +// non-nil. Fields are filled in by jacobsa/fuse; file system implementations +// can add their own fields by writing to the Extra map. type WireLogRecord struct { Operation string StartTime time.Time Duration time.Duration Status int Context *fuseops.OpContext - Args map[string]any + Args map[string]any // Serialized representation of the fuseops.*Op struct Extra map[string]any // Custom fields added by file system implementation } -// Params that are ignored var ignoredParams = []string{"OpContext", "Dst", "Data"} -// Format a wire log entry func formatWireLogEntry(op any, opErr error, wlog *WireLogRecord) ([]byte, error) { v := reflect.ValueOf(op).Elem() t := v.Type()