WriteRequest differences between OSX and Linux

[whyrusleeping]

I have a test that tests writing to a fuse filesystem one byte at a time. This test passes in linux, but does not in OSX. Inspecting it further, i see that the write requests in linux are [Offset = i, Size = 1], but on OSX they are [Offset = 0, Size = i] where i is 0 to N. Is t Is this expected behaviour? or is this a bug?

[tv42]

Update: I commented out the t.Skip, and see both failures and successes. Digging deeper.

loota:~ tv$ uname -a
Darwin loota.local 13.4.0 Darwin Kernel Version 13.4.0: Sun Aug 17 19:50:11 PDT 2014; root:xnu-2422.115.4~1/RELEASE_X86_64 x86_64
loota:~ tv$ ./ipns.test -test.v -test.run=TestMultiWrite
=== RUN TestMultiWrite
--- PASS: TestMultiWrite (2.43s)
PASS
loota:~ tv$ ./ipns.test -test.v -test.run=TestMultiWrite
=== RUN TestMultiWrite
--- FAIL: TestMultiWrite (1.15s)
    ipns_test.go:334: File on disk did not match bytes written
FAIL
loota:~ tv$ ./ipns.test -test.v -test.run=TestMultiWrite
=== RUN TestMultiWrite
--- PASS: TestMultiWrite (1.13s)
PASS
loota:~ tv$ ./ipns.test -test.v -test.run=TestMultiWrite
=== RUN TestMultiWrite
--- PASS: TestMultiWrite (1.23s)
PASS
loota:~ tv$ ./ipns.test -test.v -test.run=TestMultiWrite
=== RUN TestMultiWrite
--- FAIL: TestMultiWrite (1.26s)
    ipns_test.go:334: File on disk did not match bytes written
FAIL

[tv42]

Both failing and successful test runs write 0..N bytes at offset 0, with N increasing on every write. That is, userspace adds one more byte at the end of the page cache entry, kernel flushes the page to permanent storage.

    mounted.go:109: FUSE: <- Write [ID=0x10 Node=0x4 Uid=501 Gid=20 Pid=49392] 0x1 994 @0 fl=0
    mounted.go:109: FUSE: -> ID=0x10 Write {Size:994}
    mounted.go:109: FUSE: <- Write [ID=0xe Node=0x4 Uid=501 Gid=20 Pid=49392] 0x1 995 @0 fl=0
    mounted.go:109: FUSE: -> ID=0xe Write {Size:995}

That's 994 bytes at offset 0, 995 bytes at offset 0, etc.

I don't see a difference on the FUSE level, currently.

[tv42]

Alright this looks like a reasonable explanation. From other logged data, we know that in the below snippet the write of 577 bytes has "good" data, where as the write with 578 bytes is 577 zeroes and 1 byte of good data at the end.

        mounted.go:109: FUSE: <- Write [ID=0xd Node=0x4 Uid=501 Gid=20 Pid=51496] 0x1 577 @0 fl=0
        mounted.go:109: FUSE: -> ID=0xd Write {Size:577}
        mounted.go:109: FUSE: <- Access [ID=0xc Node=0x4 Uid=501 Gid=20 Pid=45] mask=0x0
        mounted.go:109: FUSE: -> ID=0xc
        mounted.go:109: FUSE: <- Getattr [ID=0xb Node=0x4 Uid=501 Gid=20 Pid=45]
        mounted.go:109: FUSE: -> ID=0xb Getattr {AttrValid:1m0s Attr:{Inode:7599994429800982629 Size:0 Blocks:0 Atime:2014-10-20 17:15:49.938442862 -0700 PDT Mtime:2014-10-20 17:15:49.938442862 -0700 PDT Ctime:2014-10-20 17:15:49.938442862 -0700 PDT Crtime:2014-10-20 17:15:49.938442862 -0700 PDT Mode:-rw-rw-rw- Nlink:1 Uid:0 Gid:0 Rdev:0 Flags:0}}
        mounted.go:109: FUSE: <- Write [ID=0xf Node=0x4 Uid=501 Gid=20 Pid=51496] 0x1 578 @0 fl=0
        mounted.go:109: FUSE: -> ID=0xf Write {Size:578}
        mounted.go:109: FUSE: <- Write [ID=0xe Node=0x4 Uid=501 Gid=20 Pid=51496] 0x1 579 @0 fl=0
        mounted.go:109: FUSE: -> ID=0xe Write {Size:579}

So, if the attribute cache expires (usual TTL is 1 minute, as seen in AttrValid above), and the kernel re-requests attributes from your fs, you reply with "Size: 0", and this causes the kernel to truncate the file to size 0. File contents are now "", size 0.

New write comes in, saying write a byte to offset 578, the kernel expands the file to 578 bytes (with zeroes) and writes that byte.

[whyrusleeping]

Very interesting... So the issue is that an incorrect size is being returned from Attr between writes?

[tv42]

Yup. I have no idea how to get the right file size correctly for a potentially open file in ipns, but making ipns_unix.go Node.Attr have

        if size == 0 {
            size = s.dagMod.Size()
        }

with a helper function

func (dm *DagModifier) Size() uint64 {
    if dm == nil {
        return 0
    }
    return *dm.pbdata.Filesize
}

has resulted in no failures yet when running the test in a tight loop.

[tv42]

Other items to note:

• your fuse/ipns/writerat.go seems unused.
• the unixfs/io/dagmodifier_test.go TestMultiWrite behavior is actually different, this patch makes it behave more like the observed fuse behavior:

diff --git i/unixfs/io/dagmodifier_test.go w/unixfs/io/dagmodifier_test.go
index 32d9a84..5ab4e76 100644
--- i/unixfs/io/dagmodifier_test.go
+++ w/unixfs/io/dagmodifier_test.go
@@ -159,12 +159,12 @@ func TestMultiWrite(t *testing.T) {
        u.NewFastRand().Read(data)

        for i := 0; i < len(data); i++ {
-               n, err := dagmod.WriteAt(data[i:i+1], uint64(i))
+               n, err := dagmod.WriteAt(data[:i+1], 0)
                if err != nil {
                        t.Fatal(err)
                }
-               if n != 1 {
-                       t.Fatal("Somehow wrote the wrong number of bytes! (n != 1)")
+               if n != i+1 {
+                       t.Fatalf("Somehow wrote the wrong number of bytes! (%d != %d)", n, i)
                }
        }
        nd, err := dagmod.GetNode()

[tv42]

Documentation aspects filed as #47

Please open new, specific, issues if you can think of a specific thing that really needs to be better explained. "Better docs" is too vague to deserve an issue.

As far as I see, there is no bug left here, just subtle VFS behavior. And bazil.org/fuse doesn't get to dictate the rules for that, so that's not mine to fix, merely to document.

[jbenet]

@tv42 awesome, thank you very much! (haven't verified but makes sense to me!)