Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Large Setxattr causes /dev/fuse to close on OSX #42

Closed
ryanstout opened this issue Sep 29, 2014 · 19 comments
Closed

Large Setxattr causes /dev/fuse to close on OSX #42

ryanstout opened this issue Sep 29, 2014 · 19 comments

Comments

@ryanstout
Copy link

I'm not really sure what to make of this, any help would be much appreciated. On OSX, I have one file that if I copy in, it causes the fs.Serve to return. I tracked this down to here: https://github.com/bazillion/fuse/blob/master/fuse.go#L403 Basically, the syscall.Read returns n == 0 and an error with "operation not supported by device" as the .Error()

Here's what I get if I enable fuse.debug: Sorry, there's a little bit of my debugging logs in there. I'm not really sure what to make of this.

The file has an xattr of com.apple.ResourceFork. I know this is weird, but if I delete that xattr, then it works. Any ideas? Thanks

2014/09/29 14:09:10 FUSE: <- Access [ID=0xb Node=0x1 Uid=501 Gid=20 Pid=490] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xb
2014/09/29 14:09:10 FUSE: <- Access [ID=0x12 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x12
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x10 Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0x10 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xf Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xf
2014/09/29 14:09:10 FUSE: <- Access [ID=0xc Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xc
2014/09/29 14:09:10 FUSE: <- Access [ID=0x11 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: <- Access [ID=0xd Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xd
2014/09/29 14:09:10 FUSE: <- Access [ID=0x14 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x14
2014/09/29 14:09:10 FUSE: <- Access [ID=0x0 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x0
2014/09/29 14:09:10 FUSE: <- Access [ID=0xe Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xe
2014/09/29 14:09:10 FUSE: <- Lookup [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=268] "landing 2.jpg"
2014/09/29 14:09:10 FUSE: -> ID=0x5 error=ENOENT
2014/09/29 14:09:10 FUSE: <- Lookup [ID=0x1 Node=0x1 Uid=501 Gid=20 Pid=268] "landing 2.jpg"
2014/09/29 14:09:10 FUSE: -> ID=0x1 error=ENOENT
2014/09/29 14:09:10 FUSE: <- Lookup [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=268] "landing 2.jpg"
2014/09/29 14:09:10 FUSE: -> ID=0x3 error=ENOENT
2014/09/29 14:09:10 FUSE: <- Lookup [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=268] "landing 2.jpg"
2014/09/29 14:09:10 FUSE: -> ID=0x2 error=ENOENT
2014/09/29 14:09:10 FUSE: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x4
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0x7 error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0xa Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xa
2014/09/29 14:09:10 FUSE: <- Access [ID=0x8 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x8
2014/09/29 14:09:10 FUSE: <- Access [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x6
2014/09/29 14:09:10 FUSE: <- Access [ID=0x9 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x9
2014/09/29 14:09:10 FUSE: <- Access [ID=0x13 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x13
2014/09/29 14:09:10 FUSE: <- Access [ID=0xb Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xb
2014/09/29 14:09:10 FUSE: <- Lookup [ID=0x12 Node=0x1 Uid=501 Gid=20 Pid=268] "landing 2.jpg"
2014/09/29 14:09:10 FUSE: -> ID=0x12 error=ENOENT
2014/09/29 14:09:10 FUSE: <- Access [ID=0x10 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x10
2014/09/29 14:09:10 FUSE: <- Create [ID=0xf Node=0x1 Uid=501 Gid=20 Pid=268] "landing 2.jpg" fl=OpenReadWrite+OpenCreate mode=-rw-r--r--
Open: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0xf Create {LookupResponse:{Node:2 Generation:0 EntryValid:1m0s AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}} OpenResponse:{Handle:1 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Lookup [ID=0xc Node=0x1 Uid=501 Gid=20 Pid=268] "._landing 2.jpg"
2014/09/29 14:09:10 FUSE: -> ID=0xc error=ENOENT
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0x11 Node=0x2 Uid=0 Gid=0 Pid=0]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x11 Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Flush [ID=0xd Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 fl=0x0 lk=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xd
2014/09/29 14:09:10 FUSE: <- Release [ID=0x14 Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 fl=OpenReadOnly rfl=0 owner=0x0
Release: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg, true
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityFileHash
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityFileHash
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityRemoteState
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityFileSize
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityThumb
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityFileHash
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityRemoteState
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityFileSize
Set Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg: infinityThumb
2014/09/29 14:09:10 FUSE: -> ID=0x14
2014/09/29 14:09:10 FUSE: <- Access [ID=0x0 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x0
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0xe Node=0x2 Uid=501 Gid=20 Pid=268]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0xe Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x5 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0x5 error=attribute not found
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x1 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.ResourceFork" 0 @0
2014/09/29 14:09:10 FUSE: -> ID=0x1 error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x3 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x3
2014/09/29 14:09:10 FUSE: <- Access [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x2
2014/09/29 14:09:10 FUSE: <- Access [ID=0x4 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x4
2014/09/29 14:09:10 FUSE: <- Access [ID=0x7 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x7
2014/09/29 14:09:10 FUSE: <- Access [ID=0xa Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xa
2014/09/29 14:09:10 FUSE: <- Access [ID=0x8 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x8
2014/09/29 14:09:10 FUSE: <- Access [ID=0x6 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x6
2014/09/29 14:09:10 FUSE: <- Setxattr [ID=0x13 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 62726f6b4d414353000000000000000000000000000000000000000000000000 fl=8 @0x0
2014/09/29 14:09:10 FUSE: -> ID=0x13
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0xb Node=0x2 Uid=0 Gid=0 Pid=0]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0xb Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Access [ID=0x12 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x12
2014/09/29 14:09:10 FUSE: <- Access [ID=0x10 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x10
2014/09/29 14:09:10 FUSE: <- Access [ID=0xf Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xf
2014/09/29 14:09:10 FUSE: <- Access [ID=0xc Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xc
2014/09/29 14:09:10 FUSE: <- Access [ID=0x11 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: <- Access [ID=0xd Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xd
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x14 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0x14 Getxattr 62726f6b4d414353000000000000000000000000000000000000000000000000
2014/09/29 14:09:10 FUSE: <- Access [ID=0x0 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x0
2014/09/29 14:09:10 FUSE: <- Access [ID=0xe Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xe
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x5 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.ResourceFork" 0 @0
2014/09/29 14:09:10 FUSE: -> ID=0x5 error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x1 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x1
2014/09/29 14:09:10 FUSE: <- Access [ID=0x3 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x3
2014/09/29 14:09:10 FUSE: <- Access [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x2
2014/09/29 14:09:10 FUSE: <- Access [ID=0x4 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x4
2014/09/29 14:09:10 FUSE: <- Access [ID=0x7 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x7
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0xa Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0xa Getxattr 62726f6b4d414353000000000000000000000000000000000000000000000000
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x8 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.ResourceFork" 0 @0
2014/09/29 14:09:10 FUSE: -> ID=0x8 error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x6 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x6
2014/09/29 14:09:10 FUSE: <- Access [ID=0x9 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x9
2014/09/29 14:09:10 FUSE: <- Open [ID=0x13 Node=0x2 Uid=501 Gid=20 Pid=268] dir=false fl=OpenReadOnly
2014/09/29 14:09:10 FUSE: -> ID=0x13 Open {Handle:1 Flags:0}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xb Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xb
2014/09/29 14:09:10 FUSE: <- Flush [ID=0x12 Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 fl=0x0 lk=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x12
2014/09/29 14:09:10 FUSE: <- Release [ID=0x10 Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 fl=OpenReadOnly rfl=0 owner=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x10
2014/09/29 14:09:10 FUSE: <- Access [ID=0xf Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xf
2014/09/29 14:09:10 FUSE: <- Access [ID=0xc Node=0x1 Uid=501 Gid=20 Pid=81] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xc
2014/09/29 14:09:10 FUSE: <- Access [ID=0x11 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: <- Access [ID=0xd Node=0x2 Uid=501 Gid=20 Pid=81] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xd
2014/09/29 14:09:10 FUSE: <- Access [ID=0x14 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x14
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0x0 Node=0x2 Uid=501 Gid=20 Pid=81]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x0 Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xe Node=0x2 Uid=501 Gid=20 Pid=81] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0xe
2014/09/29 14:09:10 FUSE: <- Open [ID=0x5 Node=0x2 Uid=501 Gid=20 Pid=81] dir=false fl=OpenReadOnly
2014/09/29 14:09:10 FUSE: -> ID=0x5 Open {Handle:1 Flags:0}
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x1 Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0x1 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Flush [ID=0x3 Node=0x2 Uid=501 Gid=20 Pid=81] 0x1 fl=0x0 lk=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x3
2014/09/29 14:09:10 FUSE: <- Release [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=81] 0x1 fl=OpenReadOnly rfl=0 owner=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x2
2014/09/29 14:09:10 FUSE: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x4
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0x7 Node=0x2 Uid=501 Gid=20 Pid=268]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x7 Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xa Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xa
2014/09/29 14:09:10 FUSE: <- Access [ID=0x8 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x8
2014/09/29 14:09:10 FUSE: <- Access [ID=0x6 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x6
2014/09/29 14:09:10 FUSE: <- Access [ID=0x9 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x9
2014/09/29 14:09:10 FUSE: <- Access [ID=0x13 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x13
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0xb Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0xb Getxattr 62726f6b4d414353000000000000000000000000000000000000000000000000
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x12 Node=0x1 Uid=0 Gid=0 Pid=282]

2014/09/29 14:09:10 FUSE: <- Access [ID=0x10 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x12 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: -> ID=0x10
2014/09/29 14:09:10 FUSE: <- Access [ID=0xf Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xf
2014/09/29 14:09:10 FUSE: <- Access [ID=0xc Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: <- Access [ID=0x11 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: -> ID=0xc
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0xd Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.ResourceFork" 0 @0
2014/09/29 14:09:10 FUSE: -> ID=0xd error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x14 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x14
2014/09/29 14:09:10 FUSE: <- Access [ID=0x0 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x0
2014/09/29 14:09:10 FUSE: <- Access [ID=0xe Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xe
2014/09/29 14:09:10 FUSE: <- Access [ID=0x5 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x5
2014/09/29 14:09:10 FUSE: <- Access [ID=0x1 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x1
2014/09/29 14:09:10 FUSE: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x3
2014/09/29 14:09:10 FUSE: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x2
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0x4 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Access [ID=0x7 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x7
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0xa Node=0x1 Uid=0 Gid=0 Pid=282]

2014/09/29 14:09:10 FUSE: -> ID=0xa Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Access [ID=0x8 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x8
2014/09/29 14:09:10 FUSE: <- Access [ID=0x6 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x6
2014/09/29 14:09:10 FUSE: <- Access [ID=0x9 Node=0x1 Uid=0 Gid=0 Pid=282] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x9
2014/09/29 14:09:10 FUSE: <- Access [ID=0x13 Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x13
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0xb Node=0x1 Uid=501 Gid=20 Pid=12768] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0xb error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x12 Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x12
2014/09/29 14:09:10 FUSE: <- Access [ID=0x10 Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x10
2014/09/29 14:09:10 FUSE: <- Access [ID=0xf Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xf
2014/09/29 14:09:10 FUSE: <- Access [ID=0x11 Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: <- Access [ID=0xc Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xc
2014/09/29 14:09:10 FUSE: <- Access [ID=0xd Node=0x1 Uid=501 Gid=20 Pid=12768] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xd
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x14 Node=0x1 Uid=501 Gid=20 Pid=12768]

2014/09/29 14:09:10 FUSE: -> ID=0x14 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x0 Node=0x1 Uid=501 Gid=20 Pid=12768]

2014/09/29 14:09:10 FUSE: -> ID=0x0 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0xe Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0xe Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0x5 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Access [ID=0x1 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x1
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0x3 error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x2
2014/09/29 14:09:10 FUSE: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x4
2014/09/29 14:09:10 FUSE: <- Access [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x7
2014/09/29 14:09:10 FUSE: <- Access [ID=0xa Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0xa
2014/09/29 14:09:10 FUSE: <- Access [ID=0x8 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x8
2014/09/29 14:09:10 FUSE: <- Access [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x6
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x9 Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0x9 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Statfs [ID=0x13 Node=0x1 Uid=501 Gid=20 Pid=268]

2014/09/29 14:09:10 FUSE: -> ID=0x13 Statfs {Blocks:34359738368 Bfree:17179869184 Bavail:17179869184 Files:536870912 Ffree:268435456 Bsize:4194304 Namelen:2048 Frsize:0}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xb Node=0x1 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0xb
2014/09/29 14:09:10 FUSE: <- Access [ID=0x12 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x12
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0x10 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 32 @0
2014/09/29 14:09:10 FUSE: -> ID=0x10 Getxattr 62726f6b4d414353000000000000000000000000000000000000000000000000
2014/09/29 14:09:10 FUSE: <- Getxattr [ID=0xf Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.ResourceFork" 0 @0
2014/09/29 14:09:10 FUSE: -> ID=0xf error=attribute not found
2014/09/29 14:09:10 FUSE: <- Access [ID=0x11 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: <- Access [ID=0xc Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xc
2014/09/29 14:09:10 FUSE: <- Access [ID=0xd Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xd
2014/09/29 14:09:10 FUSE: <- Access [ID=0x14 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x4
2014/09/29 14:09:10 FUSE: -> ID=0x14
2014/09/29 14:09:10 FUSE: <- Access [ID=0x0 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x1
2014/09/29 14:09:10 FUSE: -> ID=0x0
2014/09/29 14:09:10 FUSE: <- Access [ID=0xe Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0xe
2014/09/29 14:09:10 FUSE: <- Access [ID=0x5 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x0
2014/09/29 14:09:10 FUSE: -> ID=0x5
2014/09/29 14:09:10 FUSE: <- Access [ID=0x1 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x1
2014/09/29 14:09:10 FUSE: <- Open [ID=0x3 Node=0x2 Uid=501 Gid=20 Pid=268] dir=false fl=OpenWriteOnly
Open: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
2014/09/29 14:09:10 FUSE: -> ID=0x3 Open {Handle:1 Flags:0}
2014/09/29 14:09:10 FUSE: <- Setattr [ID=0x2 Node=0x2 Uid=501 Gid=20 Pid=268] size=0 handle=0x1
!Setattr /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x2 Setattr {AttrValid:5s Attr:{Inode:0 Size:0 Blocks:0 Atime:0001-01-01 00:00:00 +0000 UTC Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:0001-01-01 00:00:00 +0000 UTC Crtime:0001-01-01 00:00:00 +0000 UTC Mode:-rw-r--r-- Nlink:0 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0x4 Node=0x2 Uid=0 Gid=0 Pid=0]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x4 Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Access [ID=0x7 Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0x7
2014/09/29 14:09:10 FUSE: <- Setxattr [ID=0xa Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.quarantine" 303034333b35336636623432363b476f6f676c655c7832304368726f6d652e6170703b33364436373339322d433441332d344542412d394343372d453733433844303042453638 fl=8 @0x0
2014/09/29 14:09:10 FUSE: -> ID=0xa
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0x8 Node=0x2 Uid=0 Gid=0 Pid=0]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x8 Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:0 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Write [ID=0x6 Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 131072 @0 fl=0
Write /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg - 131072 at 0
2014/09/29 14:09:10 FUSE: -> ID=0x6 Write {Size:131072}
2014/09/29 14:09:10 FUSE: <- Write [ID=0x9 Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 114688 @131072 fl=0
Write /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg - 114688 at 131072
2014/09/29 14:09:10 FUSE: -> ID=0x9 Write {Size:114688}
2014/09/29 14:09:10 FUSE: <- Write [ID=0x13 Node=0x2 Uid=501 Gid=20 Pid=268] 0x1 2771 @245760 fl=0
Write /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg - 2771 at 245760
2014/09/29 14:09:10 FUSE: -> ID=0x13 Write {Size:2771}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xb Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xb
2014/09/29 14:09:10 FUSE: <- Removexattr [ID=0x12 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo"
2014/09/29 14:09:10 FUSE: -> ID=0x12
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0x10 Node=0x2 Uid=0 Gid=0 Pid=0]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0x10 Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:248531 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xf Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xf
2014/09/29 14:09:10 FUSE: <- Setxattr [ID=0x11 Node=0x2 Uid=501 Gid=20 Pid=268] "com.apple.FinderInfo" 0000000000000000040000000000000000000000000000000000000000000000 fl=0 @0x0
2014/09/29 14:09:10 FUSE: -> ID=0x11
2014/09/29 14:09:10 FUSE: <- Getattr [ID=0xc Node=0x2 Uid=0 Gid=0 Pid=0]
Get Attr: /Users/ryanstout/Sites/infinitydrive/go/drive/landing 2.jpg
Got
2014/09/29 14:09:10 FUSE: -> ID=0xc Getattr {AttrValid:1m0s Attr:{Inode:7122798477543916100 Size:248531 Blocks:0 Atime:2014-09-29 14:08:54.350541779 -0600 MDT Mtime:2014-09-29 14:09:10 -0600 MDT Ctime:2014-09-29 14:08:54.350541779 -0600 MDT Crtime:2014-09-29 14:08:54.350541779 -0600 MDT Mode:-rw-r--r-- Nlink:1 Uid:501 Gid:20 Rdev:0 Flags:0}}
2014/09/29 14:09:10 FUSE: <- Access [ID=0xd Node=0x2 Uid=501 Gid=20 Pid=268] mask=0x2
2014/09/29 14:09:10 FUSE: -> ID=0xd
Done Running
@ryanstout
Copy link
Author

Ok, also, copying from the command line gives me the following:

cp: /Users/ryanstout/Desktop/raw_files/broken/landing 2.jpg: could not copy extended attributes to ./landing 2.jpg: Device not configured

@ryanstout
Copy link
Author

Maybe the issue is this file has a really large com.apple.ResourceFork xattr Is there some buffer limits somewhere?

@tv42
Copy link
Member

tv42 commented Sep 29, 2014

What you're seeing from Serve is osxfuse slamming the door shut on you. That's just collateral damage from whatever actually went wrong.

Why that happens is a tougher question. The cp getting that error sounds like key. It's pretty definitely about xattr manipulation, and the resource fork stuff is a special case backwards compatibility thing that was sort of kludged on top the xattr api -- it wouldn't surprise me at all if something went wrong in handling it. See also #31.

I'm pretty badly in the middle of a move, but I promise to look at this better in a few weeks. If you can post a small reproducing example, that will significantly ease my role. You should be able to eliminate the actual cp and just set/get resource fork related things.

@ryanstout
Copy link
Author

@tv42 Thanks. Best of luck on the move. I'm narrowing things down now. I'm pretty sure its something to do with large xattr's. I'm going to change the size of this attr and see if it works when its smaller. I'll let you know, thanks!

@ryanstout
Copy link
Author

@tv42 Ok, I tracked it down. Looks like the issue is the size of https://github.com/bazillion/fuse/blob/master/fuse.go#L291 Here it doesn't check the bounds: https://github.com/bazillion/fuse/blob/master/fuse.go#L393 Any ideas on the best way to fix this? Thanks

@tv42
Copy link
Member

tv42 commented Sep 29, 2014

@ryanstout I'm not sure what you mean by that. newMessage allocates m.buf as a bufSize-length []byte, then there's n, err := syscall.Read(..., m.buf) and m.buf = m.buf[:n].

@ryanstout
Copy link
Author

@tv42 So I might be off, but it looks like syscall.Read isn't checking on the size of m.buf, its just copying in. (Buffer overrun?)

@ryanstout
Copy link
Author

I checked, increasing the buffer made it work for me (for that file)

@mfrister
Copy link

mfrister commented Oct 8, 2014

This might be related to #12, where I had problems with the buffer receiving data from the kernel when increasing iosize. I can imagine that cp tries to put a chunk into the ResourceFork xattr that's larger than buffer.

@tv42
Copy link
Member

tv42 commented Oct 31, 2014

@meeee #12 was caused by me dropping the -o iosize as part of a cleanup/rewrite, thinking osxfuse would respect InitResponse.MaxWrite like Linux seems to. I should just stop expecting osxfuse to be compatible.

@ryanstout I am quite convinced your doubts about the Read vs bufSize is a red herring, and you saw it work because of confirmation bias. Your underlying bug sounds more dependent on some sort of a timing issue, probably with the dentry cache timing out at just the wrong time.

Right now, I have no guess on the actual cause, but the cp error message about extended attributes sounds totally plausible.

I feel like to make progress, we need to isolate the problem into something smaller and more easily reproducible. Is your code open source?

@tv42
Copy link
Member

tv42 commented Oct 31, 2014

Hmm large xattrs don't currently have tests, and there's no way for the OS to chunk the setxattr into smaller operations (apart from that abandoned remnant of resource fork, that has a Position).. it might actually be that, in order to support larger xattrs, we need to bump up InitResponse.MaxWrite/-o iosize=. Time to add some tests..

@tv42
Copy link
Member

tv42 commented Oct 31, 2014

Once I push the xattr value above 128kB (maxWrite):

Linux: the syscallx.Setxattr client call sees E2BIG error.

OS X:

2014/10/30 19:40:41 FUSE: short kernel write: written=-1/128 error="socket is not connected" stack=
goroutine 28 [running]:
bazil.org/fuse.stack(0x0, 0x0)
    /home/tv/go/src/bazil.org/fuse/debug.go:9 +0x84
bazil.org/fuse.(*Conn).respond(0x2083a8240, 0x2084474d8, 0x80)
    /home/tv/go/src/bazil.org/fuse/fuse.go:863 +0x169
bazil.org/fuse.(*GetattrRequest).Respond(0x2083ace10, 0x2083d61e0)
    /home/tv/go/src/bazil.org/fuse/fuse.go:1072 +0x138
bazil.org/fuse/fs.(*serveConn).serve(0x2083d6000, 0x2208387d40, 0x2083ace10)
    /home/tv/go/src/bazil.org/fuse/fs/serve.go:750 +0x5c24
created by bazil.org/fuse/fs.(*Server).Serve
    /home/tv/go/src/bazil.org/fuse/fs/serve.go:334 +0x6ef

and a hang.

Lovely. What an amazing job of error handling osxfuse is doing there.

@ryanstout
Copy link
Author

@tv42 basically it looks like it's just osxfuse not respecting the
MaxWrite/iosize. It's not a timing issue, it fails every time with a file
with a large xattr. Increasing the MaxWrite buffer in Brazil/fuse fixes it,
but makes it slow since I need to make the buffer huge. If your around
tomorrow I'll hit you up. Thanks.
On Thu, Oct 30, 2014 at 8:41 PM Tv notifications@github.com wrote:

Once I push the xattr value above 128kB (maxWrite):

Linux: the syscallx.Setxattr client call sees E2BIG error.

OS X:

2014/10/30 19:40:41 FUSE: short kernel write: written=-1/128 error="socket is not connected" stack=
goroutine 28 [running]:bazil.org/fuse.stack(0x0, 0x0)
/home/tv/go/src/bazil.org/fuse/debug.go:9 +0x84bazil.org/fuse.(_Conn).respond(0x2083a8240, 0x2084474d8, 0x80)
/home/tv/go/src/bazil.org/fuse/fuse.go:863 +0x169bazil.org/fuse.(_GetattrRequest).Respond(0x2083ace10, 0x2083d61e0)
/home/tv/go/src/bazil.org/fuse/fuse.go:1072 +0x138bazil.org/fuse/fs.(_serveConn).serve(0x2083d6000, 0x2208387d40, 0x2083ace10)
/home/tv/go/src/bazil.org/fuse/fs/serve.go:750 +0x5c24
created by bazil.org/fuse/fs.(_Server).Serve
/home/tv/go/src/bazil.org/fuse/fs/serve.go:334 +0x6ef

and a hang.

Lovely. What an amazing job of error handling osxfuse is doing there.


Reply to this email directly or view it on GitHub
#42 (comment).

@tv42
Copy link
Member

tv42 commented Oct 31, 2014

Reading https://github.com/osxfuse/kext/blob/a8a109b0081f9b227e5fd2f551604a22d7afef95/fuse_vnops.c#L3273 tells me osxfuse setxattr will return E2BIG only if the xattr value is >16MB (FUSE_DEFAULT_USERKERNEL_BUFSIZE or adjustable apparently globally with a sysctl; not per fuse mount I think). This test also seems to fail to account for the rest of the message, testing just the attribute size; that's probably an osxfuse bug.

I don't quite understand what the fdisp_make_vp_canfail thing is (sounds like it's bookkeeping for the pending requests waiting for a response from the userspace), but since that early return does not trigger, we can assume the problem is not there. (https://github.com/osxfuse/kext/blob/a8a109b0081f9b227e5fd2f551604a22d7afef95/fuse_vnops.c#L3280 )

Next up, there's a hard limit that prevents attrsize > FUSE_REASONABLE_XATTRSIZE (= FUSE_MIN_USERKERNEL_BUFSIZE = 128kB). That min is the minimum value for the sysctl mentioned above. Once again, this seems to fail to account for the rest of the message, probably another osxfuse bug.

I don't know much about darwin, but it seems like the actual killing of /dev/fuse happens in fuse_device_read as it notices it has a message that wasn't fully consumed by a single read: https://github.com/osxfuse/kext/blob/a8a109b0081f9b227e5fd2f551604a22d7afef95/fuse_device.c#L377

So yeah. OSXFUSE does not respect MaxWrite / iosize for setxattr, and fails to handle the error properly (E2BIG).

A workaround would be to bump MaxWrite to 128kB (FUSE_REASONABLE_XATTRSIZE above), but I'm hesitant to do that easily because the serving loop already creates quite a lot of garbage; I feel like it needs a buffer reuse mechanism, before a buffer that large is reasonable. Increasing it less than that would just make this crash more rare.

Sorry about trying to pin this on something else, you did figure out the right cause; I just didn't want to believe you, because I didn't want to believe in osxfuse failing this badly. In the linux code, the logic for "request won't fit -> make it crap out logic is universal and trivially simple: https://github.com/torvalds/linux/blob/3a2f22b7d0cc64482a91529e23c2570aa0602fa6/fs/fuse/dev.c#L1237

I'm bummed about osxfuse.

@tv42
Copy link
Member

tv42 commented Oct 31, 2014

So given that maxWrite is already 128kB, I can get a setxattr(..., "greeting", 120,000 bytes of hello world) to work just fine.

Going above that, a ~1.2MB xattr value does cause the same old /dev/fuse close. So the FUSE_REASONABLE_XATTRSIZE limit does not seem to work right, either?

Going above 16MB does cause setxattr to get E2BIG.

Even dropping the global tunable buffersize from 16MB to 128kB with sudo sysctl -w osxfuse.tunables.userkernel_bufsize=131072 does not make the setxattr give a pretty error, it still just closes /dev/fuse. This sounds like an osxfuse bug here. Given that, I don't see how we could run reliably in a mode where maxWrite <16MB; osxfuse closes /dev/fuse when it should just return an error.

Can you figure out what the xattr value you had actually was? Is it >128kB but <16MB?

As a workaround, bumping maxWrite to the full 16MB (only on Darwin) will cause a lot more GC churn, but at least it'll be harder to make it fail.

@ryanstout
Copy link
Author

@tv42 Thanks for looking into it. I'm going to hit you up on IM here in a few. The file I was testing has 883k in a xattr. I tried bumping up the buffer to 16MB, but it makes things really slow. Is it possible to reuse the buffer, or would that cause race conditions?

Thanks

@ryanstout
Copy link
Author

Like would it be possible to have a buffer pool? That might actually make things faster since you wouldn't need to be mallocing so often (which I assume is happening now).

@tv42
Copy link
Member

tv42 commented Oct 31, 2014

Yes, I want to use sync.Pool for it, but that means I need to first audit the code to see whether returning the buffer to the pool is safe in Respond/RespondError, or whether somebody holds on to it longer. And then change the docs to say you must not use it after responding.

@tv42 tv42 closed this as completed in a386bed Nov 4, 2014
@tv42 tv42 changed the title OSX issue. Large Setxattr causes /dev/fuse to close on OSX Nov 7, 2014
tv42 added a commit that referenced this issue Jun 24, 2016
OSX is kept at 16MB to avoid triggering a bug with large Setxattr
calls: #42

While this was already using sync.Pool and in theory reusing the
buffers, real world isn't as merciful. Apparently 2*16MB plus some
waste from other parts of the system was enough to keep triggering GC
runs all too often. Decreasing the buffer size helps keep us below
that threshold.

New buffer size is the largest Write payload size observed on Linux,
and the most common size for write-heavy workloads.

Improves performance and decreases memory use on Linux.

Thanks to Aaron Jacobs <jacobsa@google.com>
and Damien Tournoud <damien@platform.sh>.
@tv42
Copy link
Member

tv42 commented Jun 30, 2016

For posterity: the OSXFUSE large setxattr bug is reported as macfuse/macfuse#293

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants