search

google-code-export / camlistore

Automatically exported from code.google.com/p/camlistore
Apache License 2.0
0 stars 0 forks source link

camlifuse broken/erradic behavior in ToT #556

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
camlifuse seems to be broken in master (works in 0.8), possibly in the 
"bazil.org/fuse" import, which seems to be the only commit involving fuse in 
the timeframe since 0.8. 

Symptoms include:

Dragging 4-5 files into a root: Finder reporting "The operation can’t be 
completed because an item with the name “KIT_01344.jpg” already exists."

None of the items show up in finder, and another DnD of the same files results 
in: "The item “KIT_01345.jpg” can’t be replaced because it’s invisible."

ls -l shows that all of the files "are there", and while some have been copied 
and have a proper size, others have a 0 size and seem to have failed upload.

Re-starting camlimount results in the files appearing in Finder again, the 
0-size files with a transparent/hidden rendering.

Creating a directory and setting a Finder label on it results in the folder 
disappearing. Creating another folder or copying files will sometimes bring it 
back from the dead, only to disappear again after another operation.

Original issue reported on code.google.com by tora...@gmail.com on 7 Dec 2014 at 6:27

GoogleCodeExporter commented 9 years ago 
Dragging a single file into a new root using Finder:

2014/12/07 23:43:23 mutDir("test").Lookup("KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 Created &mutFile{0xc214830d80 name="test/KIT_01195.jpg" 
perm:sha1-35c13e88d360f815bee72c3d033e48677cc31978} in 0xc214617600
2014/12/07 23:43:23 mutDir("test").Lookup("._KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 mutFile.setxattr("com.apple.FinderInfo") -> 
"brokMACS\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0
0\x00\x00\x00\x00\x00\x00"
2014/12/07 23:43:23 mutDir("test").Lookup(".DS_Store") = <nil>, no such file or 
directory
2014/12/07 23:43:23 mutDir("test").Lookup(".DS_Store") = <nil>, no such file or 
directory
2014/12/07 23:43:23 mutDir("test").Lookup(".DS_Store") = <nil>, no such file or 
directory
2014/12/07 23:43:23 mutDir("test").Lookup(".DS_Store") = <nil>, no such file or 
directory
2014/12/07 23:43:23 mutDir("test").Lookup(".DS_Store") = <nil>, no such file or 
directory
2014/12/07 23:43:23 mutFile.Open: 
sha1-35c13e88d360f815bee72c3d033e48677cc31978: content: 
sha1-128918ed01100580b5db671b073fd3bc8a31be25 dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-128918ed01100580b5db671b073fd3bc8a31be25
2014/12/07 23:43:23 mutFile.Open: 
sha1-35c13e88d360f815bee72c3d033e48677cc31978: content: 
sha1-128918ed01100580b5db671b073fd3bc8a31be25 dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-128918ed01100580b5db671b073fd3bc8a31be25
2014/12/07 23:43:23 Created &mutFile{0xc214d4b680 name="test/.DS_Store" 
perm:sha1-b096d3c3b43b15be837476801f2b461deae9d8ae} in 0xc214617600
2014/12/07 23:43:23 mutDir("test").Lookup("._.DS_Store") = <nil>, no such file 
or directory
2014/12/07 23:43:23 mutFile.Open: 
sha1-35c13e88d360f815bee72c3d033e48677cc31978: content: 
sha1-128918ed01100580b5db671b073fd3bc8a31be25 dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-128918ed01100580b5db671b073fd3bc8a31be25
2014/12/07 23:43:23 mutFile.Open: 
sha1-35c13e88d360f815bee72c3d033e48677cc31978: content: 
sha1-128918ed01100580b5db671b073fd3bc8a31be25 dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-128918ed01100580b5db671b073fd3bc8a31be25
2014/12/07 23:43:23 mutFile.setxattr("com.apple.FinderInfo") -> "        
\x00\x10\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
\x00\x00\x00\x00"
2014/12/07 23:43:23 mutDir("test").Lookup("KIT_01195.jpg") = 
&mutFile{0xc214830d80 name="test/KIT_01195.jpg" 
perm:sha1-35c13e88d360f815bee72c3d033e48677cc31978}, <nil>
2014/12/07 23:43:23 mutFile.Open: 
sha1-b096d3c3b43b15be837476801f2b461deae9d8ae: content: 
sha1-331e75cdfccb0648746d31a8911e142024fd8d1d dir=false flags=OpenWriteOnly
2014/12/07 23:43:23 mutFile.Open returning read-write filehandle
2014/12/07 23:43:23 mutFile.Setattr on "test/.DS_Store": 
&fuse.SetattrRequest{Header:fuse.Header{Conn:(*fuse.Conn)(0xc208004a80), 
ID:0x4, Node:0xf, Uid:0x1f5, Gid:0x14, Pid:0x3183, 
msg:(*fuse.message)(0xc208024de0)}, Valid:0x48, Handle:0x1, Size:0x0, 
Atime:time.Time{sec:6090230075449538304, nsec:0x0, 
loc:(*time.Location)(0x915960)}, Mtime:time.Time{sec:327641444742461184, 
nsec:0x48c041a, loc:(*time.Location)(0x915960)}, Mode:0x44001ee, Uid:0x48c041a, 
Gid:0x0, Bkuptime:time.Time{sec:142448891393812, nsec:0xc, 
loc:(*time.Location)(0x915960)}, Chgtime:time.Time{sec:92200367872, nsec:0x0, 
loc:(*time.Location)(0x915960)}, Crtime:time.Time{sec:0, nsec:0x0, 
loc:(*time.Location)(nil)}, Flags:0x0}
2014/12/07 23:43:23 Removed &mutFile{0xc214830d80 name="test/KIT_01195.jpg" 
perm:sha1-35c13e88d360f815bee72c3d033e48677cc31978} from 0xc214617600
2014/12/07 23:43:23 mutDir("test").Lookup("._KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 mutFileHandle.Write("test/.DS_Store", 4 bytes at 0, flags 
0) = 4, <nil>
2014/12/07 23:43:23 mutFile.setSizeAtLeast(4). old size = 0
2014/12/07 23:43:23 mutFile.Open: 
sha1-b096d3c3b43b15be837476801f2b461deae9d8ae: content: 
sha1-331e75cdfccb0648746d31a8911e142024fd8d1d dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader READ on 
sha1-331e75cdfccb0648746d31a8911e142024fd8d1d: 
&fuse.ReadRequest{Header:fuse.Header{Conn:(*fuse.Conn)(0xc208004a80), ID:0x2, 
Node:0xf, Uid:0x1f5, Gid:0x14, Pid:0x3183, msg:(*fuse.message)(0xc208024de0)}, 
Dir:false, Handle:0x2, Offset:0, Size:4096}
2014/12/07 23:43:23 mutFileHandle.Write("test/.DS_Store", 6148 bytes at 0, 
flags 0) = 6148, <nil>
2014/12/07 23:43:23 mutFile.setSizeAtLeast(6148). old size = 4
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-331e75cdfccb0648746d31a8911e142024fd8d1d
2014/12/07 23:43:23 mutDir("test") appending inode b096d3c3b43b15be, 
{Inode:12724590634677769662 Type:unknown Name:.DS_Store}
2014/12/07 23:43:23 mutDir("test").Lookup("KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 mutDir("test").Lookup("KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 mutDir("test").Lookup("KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 mutDir("test").Lookup("KIT_01195.jpg") = <nil>, no such 
file or directory
2014/12/07 23:43:23 mutFile.Open: 
sha1-b096d3c3b43b15be837476801f2b461deae9d8ae: content: 
sha1-bd683c12583b955119c9623019576221d7dda033 dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-bd683c12583b955119c9623019576221d7dda033
2014/12/07 23:43:23 mutFile.Open: 
sha1-b096d3c3b43b15be837476801f2b461deae9d8ae: content: 
sha1-bd683c12583b955119c9623019576221d7dda033 dir=false flags=OpenReadOnly
2014/12/07 23:43:23 mutFile.Open returning read-only file
2014/12/07 23:43:23 CAMLI nodeReader RELEASE on 
sha1-bd683c12583b955119c9623019576221d7dda033
2014/12/07 23:43:24 mutDir("test") appending inode b096d3c3b43b15be, 
{Inode:12724590634677769662 Type:unknown Name:.DS_Store}

"The operation can’t be completed because an item with the name 
“KIT_01195.jpg” already exists."

Original comment by tora...@gmail.com on 7 Dec 2014 at 10:47

GoogleCodeExporter commented 9 years ago 
At a commit 31ebc20ba78bf9bb890b3868ca7b0ca5914917fe (so post bazil.org/fuse 
update), creating a new dir in roots, and copying a file in that new dir works 
for me, on Linux that is.

So unless I misunderstood your use-case I can't reproduce your issue, which 
might then be OSX specific.

A few questions to be clear:
1) is camlifuse an OSX specific program, or are you just referring to the 
ability to use the fuse interface for Camlistore?
2) by camlimount, I assume you mean cammount?
3) what is ToT ?

Could someone with OSX reproduce the issue and confirm it was introduced with 
commitba447185d46f7dd24a444a368214d8da74060d0f please?

tagging it 0.9 since it seems to be a regression.

Original comment by mathieu....@gmail.com on 8 Dec 2014 at 6:08

GoogleCodeExporter commented 9 years ago 
The log included in comment 1 doesn't seem to match the behavior in the 
original issue; all errors I can see are "no such file or directory", no EEXIST 
there.

Of course, Finder piles on a bunch of magic that can be hard to figure out. 
What's the behavior on the command line?

I really need to see fuse.Debug style logs to be of much help, I don't know the 
situations in which those camli debug messages from comment 1 are output.

Original comment by tommi.vi...@gmail.com on 8 Dec 2014 at 6:24

GoogleCodeExporter commented 9 years ago 
Apologies, I was being unclear in my initial bug report.

Platform is OSX 10.10
Tool is cammount
"ToT" means Tip of Tree, ie. master/HEAD. I've bisected the issue down to 
commit 5fe955c, the merge of the "bazil.org/fuse" update (ba447185d46f7d). The 
commit before that seems fine.

Here's a log of cammount -debug /tmp/camli, creating and opening 
/tmp/camli/roots/5fe955c in Finder, then copying in one and one jpg image:

  https://gist.github.com/torarnv/bf95fbfca719c8a42aa5 

- Some files failed with "The operation can’t be completed because an item 
with the name '<foo>' already exists."
- All of them show as "hidden" when initially copied, with a transparent icon, 
and a gray Finder-tag:

 https://www.dropbox.com/s/3kqn598vetxlxb9/Screenshot%202014-12-08%2020.44.36.png?dl=0

- After copying more files, some of them will suddenly go to not being hidden, 
and generate a thumbnail:

  https://www.dropbox.com/s/a629xoiyekyf8yd/Screenshot%202014-12-08%2020.45.01.png?dl=0

- Adding a folder and tagging it with the "Green" tag makes it look like a file 
in Finder, with no icon, and it becomes transparent:

  https://www.dropbox.com/s/79dhjvgl92elr8e/Screenshot%202014-12-08%2020.45.38.png?dl=0

Here is a log from the terminal, trying to poke at the directory outside of 
Finder:

  https://gist.github.com/torarnv/20139803108d9adce63b

Original comment by tora...@gmail.com on 8 Dec 2014 at 8:06

GoogleCodeExporter commented 9 years ago 
More info: After creating a directory inside /tmp/camli/roots/5fe955c in the 
terminal, and copying some photos there using cp, they upload to camlistore 
fine, and i can open them in the OSX Preview app just fine:

{vegas:/private/tmp/camli/roots/5fe955c/hei} $ ls -al
total 32528
-rw-------  1 torarne  staff  1524152 Dec  8 21:09 IMG_3330.JPG
-rw-------  1 torarne  staff  1646794 Dec  8 21:09 IMG_3331.JPG
-rw-------  1 torarne  staff  1590169 Dec  8 21:09 IMG_3332.JPG
-rw-------  1 torarne  staff  1597166 Dec  8 21:09 IMG_3333.JPG
-rw-------  1 torarne  staff  1619805 Dec  8 21:09 IMG_3334.JPG
-rw-------  1 torarne  staff  1704270 Dec  8 21:09 IMG_3335.JPG
-rw-------  1 torarne  staff  1763025 Dec  8 21:09 IMG_3336.JPG
-rw-------  1 torarne  staff  1592349 Dec  8 21:09 IMG_3337.JPG
-rw-------  1 torarne  staff  1725136 Dec  8 21:09 IMG_3338.JPG
-rw-------  1 torarne  staff  1865030 Dec  8 21:09 IMG_3339.JPG
{vegas:/private/tmp/camli/roots/5fe955c/hei} $ open IMG_3330.JPG
{vegas:/private/tmp/camli/roots/5fe955c/hei} $ open IMG_3331.JPG
{vegas:/private/tmp/camli/roots/5fe955c/hei} $ open IMG_3339.JPG
{vegas:/private/tmp/camli/roots/5fe955c/hei} $ # all okey

But, the moment i open the folder itself in Finder, Finder blocks completely, 
until cammount crashes with "short kernel write: written=-1/16 error="socket is 
not connected":

{vegas:/private/tmp/camli/roots/5fe955c/hei} $ open .

https://gist.github.com/torarnv/59636c89b91d204936db

Original comment by tora...@gmail.com on 8 Dec 2014 at 8:15

GoogleCodeExporter commented 9 years ago 
In https://gist.github.com/torarnv/bf95fbfca719c8a42aa5 OSXFUSE is sending a 
Remove and Lookup for the same dentry concurrently. That sounds horribly wrong 
to me, given what I know of Linux VFS and its assumptions. That might imply an 
OSXFUSE bug.

2014/12/08 20:42:44 <- Remove [ID=0x7 Node=0x3 Uid=501 Gid=20 Pid=14473] 
"KIT_01202.jpg" dir=false
2014/12/08 20:42:44 <- Lookup [ID=0x1 Node=0x3 Uid=501 Gid=20 Pid=12675] 
"KIT_01202.jpg"
...
2014/12/08 20:42:44 -> ID=0x1 Lookup {Node:9 Generation:0 EntryValid:1m0s 
AttrValid:1m0s Attr:{Inode:3942841720075942319 Size:0 Blocks:0 Atime:2014-12-08 
20:42:21.992901609 +0100 CET Mtime:2014-12-08 20:42:21.992901609 +0100 CET 
Ctime:2014-12-08 20:42:21.992901609 +0100 CET Crtime:2014-12-08 
20:42:21.992901609 +0100 CET Mode:-rw------- Nlink:1 Uid:501 Gid:20 Rdev:0 
Flags:0}}
...
... a lot later ...
...
2014/12/08 20:42:44 -> ID=0x7

Let me repeat myself, please try to find a way to reproduce without Finder, 
Finder adds noise and requires manual steps, debugging its actions is painful.

Original comment by tommi.vi...@gmail.com on 9 Dec 2014 at 5:31

GoogleCodeExporter commented 9 years ago 
As for https://gist.github.com/torarnv/59636c89b91d204936db in comment #5, that 
means OSXFUSE closed the connection. The question is, why? The easiest way to 
find the answer is usually in dmesg. As a guess, I'd say in this case it's this:

2014/12/08 21:11:06 <- Access [ID=0x1 Node=0xa Uid=501 Gid=20 Pid=232] mask=0x0
2014/12/08 21:12:06 -> ID=0x1

OSXFUSE services just cannot take a full minute to respond to a request. The 
way the OSXFUSE author explains it is, if osxfuse-kext didn't time out the 
requests, the Darwin kernel would hang. (Why osxfuse doesn't use fuse's 
per-request interrupt mechanism, I have no idea. It probably should.)

Original comment by tommi.vi...@gmail.com on 9 Dec 2014 at 5:37

GoogleCodeExporter commented 9 years ago 
Thanks! I'll try to reproduce it without Finder to make it easier to track down 
how to fix the bug, but I suspect Finder's actions part of the cause.

In the meantime commit 5fe955c should probably be reverted along with the 
volume name fix, as that seemed to be the reason for the update of 3rdparty 
"bazil.org/fuse", so that 0.9 doesn't ship with a broken cammount on OSX (for 
people using Finder, which is likely they will).

Original comment by tora...@gmail.com on 9 Dec 2014 at 5:43

GoogleCodeExporter commented 9 years ago 
This issue has moved to https://camlistore.org/issue/556

Original comment by bradfitz on 14 Dec 2014 at 11:40