Strange conflict with Mavericks Finder?

Ernst Mulder's Avatar

Ernst Mulder

11 Nov, 2013 03:02 PM

Hello,

On multiple machines I have encountered a strange phenomenon where, after having used CCC (3.5.3), deleting files in the Finder will produce a -43 error. A trace using fs_usage revealed that (and this happens every time) just before showing the -43 error the Finder tries to access a temp file (trying to delete the file "Trackball Works 1.1.1.dmg" It might be a coincidence and maybe CCC isn't involved at all of course but so far that's the only pointer I have. Killing the Finder solves the problem by the way.

15:39:26.913385 fsgetpath /Users/pooh/Downloads/Trackball Works 1.1.1.dmg 0.000004 Finder.7332730
15:39:26.913438 getattrlist /Users/pooh/Downloads/Trackball Works 1.1.1.dmg 0.000029 Finder.7332730
15:39:26.913492 getattrlist /Users/pooh/Downloads/Trackball Works 1.1.1.dmg 0.000009 Finder.7332730
15:39:26.913542 getattrlist [ 2] /private/tmp/com.bombich.ccc.kYppXf/private>>>>>>>>>>>>> 0.000025 Finder.7332730
15:39:26.913592 open_extended 2 /private/tmp/com.bombich.ccc.kYppXf/private>>>>>>>>>>>>> 0.000022 Finder.7332730
15:39:26.913757 fsgetpath /Users/pooh/Downloads/Trackball Works 1.1.1.dmg 0.000005 Finder.7332730
15:39:26.913773 getattrlist /Users/pooh/Downloads/Trackball Works 1.1.1.dmg 0.000006 Finder.7332730
15:39:26.913891 lstat64 /System/Library/CoreServices/Finder.app/Contents/Resources/English.lproj/ProgressStatusView1Line.nib 0.000023 Finder.3942815

  1. Support Staff 1 Posted by Sarah Bombich on 11 Nov, 2013 10:23 PM

    Sarah Bombich's Avatar

    Hi Ernst,

    CCC consistently sees 'Trackball Works' as a mounted .dmg volume and I suspect your errors relates to temporary files that are in use while mounted. Further, it looks like an installer is likely on the dmg and I wonder if you recently installed the Trackball Works program and it didn't cleanly exit. Try unmounting Trackball Works by dragging it to the trash, delete the .dmg file from your Downloads folder, and then re-run your task. If that doesn't clear up your errors, try restarting and then re-run your task.

    Best of luck,
    Sarah

  2. 2 Posted by Ernst Mulder on 12 Nov, 2013 01:56 PM

    Ernst Mulder's Avatar

    Hello Sarah,

    Your misunderstanding the issue. Let me try to elaborate. "Trackball Works" was a random example, any other file I tried produced the same issue.

    The following phenomenon is reproducible (I've been able to reproduce it on three different Mavericks systems) although some timing issue is involved.

    1) Start CCC on a Mavericks Mac.

    2) Quit CCC after a short while, preferably after performing some operations. CCC wil have created directories in /private/tmp starting with "com.bombich.ccc." followed by a random ID. Two per launch of CCC.

    3) Wait. After a while try to delete a random file in the Finder and you'll get an error. This doesn't happen immediately. I had to wait minutes in this particular case. I haven't found the exact trigger yet. It may not have to do anything with actions within CCC. After a while unmount (triggered by what?) tries to unmount /private/tmp/com.bombich.ccc.<id>/.Trashes which might be part of the issue.

    After that you won't be able to delete any file in the Finder. Trying to do so yields the following error:

    The following lines are visible in the output of fs_usage.

    14:33:28.975065 WrMeta[A] D=0x00000002 B=0x200 /dev/disk0s3 /private/tmp/com.bombich.ccc.uXcLUE 0.000255 W umount.146789
    14:33:28.975185 WrMeta[A] D=0x00021080 B=0x1000 /dev/disk0s3 /private/tmp/com.bombich.ccc.TJDsoD/.Trashes 0.000289 W umount.146789
    14:33:28.975290 WrMeta[A] D=0x00021088 B=0x1000 /dev/disk0s3 /private/tmp/com.bombich.ccc.TJDsoD/.Trashes 0.000377 W umount.146789
    14:33:28.975391 WrMeta[A] D=0x00021090 B=0x1000 /dev/disk0s3 /private/tmp/com.bombich.ccc.TJDsoD/.Trashes 0.000463 W umount.146789
    14:33:28.992935 WrMeta[A] D=0x00000002 B=0x200 /dev/disk0s3 /private/tmp/com.bombich.ccc.TJDsoD 0.000166 W umount.146789
    14:33:29.022533 unmount /private/tmp/com.bombich.ccc.TJDsoD 0.055260 W umount.146789

    14:35:45.182679 getattrlist [ 2] /private/tmp/com.bombich.ccc.TJDsoD/private>>>>>>>>>>>>> 0.000018 Finder.147902
    14:35:45.182718 open_extended [ 2] (_WC__E) /private/tmp/com.bombich.ccc.TJDsoD/private>>>>>>>>>>>>> 0.000017 Finder.147902

    5) The issue will disappear after either restarting the Finder or removing the "com.bombich.ccc." temp directories using other means (i.e. the Terminal).

    The Finder seems to assume there's a .Trashes subdirectory under CCC's temp directories, or Mavericks thinks the temp directory are mounted file systems?

    Ernst Mulder

  3. Support Staff 3 Posted by Mike Bombich on 12 Nov, 2013 04:32 PM

    Mike Bombich's Avatar

    Hi Ernst:

    Thanks for the report, and thanks for taking the time to dig into this one. I have actually seen the same behavior on my test system, though I assumed it was just another buggy Finder issue.

    The following lines are visible in the output of fs_usage. 14:33:28.975065 WrMeta[A] D=0x00000002 B=0x200 /dev/disk0s3 /private/tmp/com.bombich.ccc.uXcLUE 0.000255 W umount.146789

    I don't think these are related, but I will verify. When you open CCC, CCC will collect information about all mounted volumes, and it will also mount any "Recovery HD" volumes that it can find to determine what OS is installed on them. To avoid these popping up in the Finder, CCC mounts these volumes privately at custom mountpoints, in the format of /private/tmp/com.bombich.ccc.XXXXXX. Once CCC has collected the information it needs, it unmounts these volumes. Those mountpoint folders should be deleted (I just fixed that right now), but again I don't think this is related. The fs_usage output indicates that it is the "umount" application that is accessing those folders, and that's due to CCC unmounting those volumes. These things happen without any other activity in CCC, though, so simply opening and quitting CCC would cause these volumes to be mounted and unmounted.

    Ah, well this one could be related:

    14:35:45.182679 getattrlist [ 2] /private/tmp/com.bombich.ccc.TJDsoD/private>>>>>>>>>>>>> 0.000018 Finder.147902

    It looks like Finder is trying to read a file on that Recovery HD volume. Based on the timing, Finder was pretty late to the party, the associated volume was unmounted a while before that access attempt was made. That mountpoint was still present, though, so maybe that is related...

    ...

    Ok, I was able to reproduce that error and do some digging of my own. The error indicates that some items can't be found, and I see this fs_usage output:

    10:53:20.322127  getattrlist            [  2]           /Users/apple/Library/Mobile Documents                                                    0.000039   Finder.1501
    10:53:20.323422  fsgetpath                              /Users/apple/Desktop/mnt.sh                                                              0.000006   Finder.4743
    10:53:20.323480  getattrlist                            /Users/apple                                                                             0.000015   Finder.4743
    10:53:20.323637  fsgetpath                              /Users/apple/Desktop/mnt.sh                                                              0.000005   Finder.4743
    10:53:20.323749  getattrlist                            /Users/apple/Desktop/mnt.sh                                                              0.000013   Finder.4743
    10:53:20.323802  getattrlist            [  2]           /private/tmp/com.bombich.ccc.7LcYgG>>>>>>>>>>>>>>>>>>>>>                                 0.000018   Finder.4743
    10:53:20.323850  open_extended          [  2] (_WC__E)  /private/tmp/com.bombich.ccc.7LcYgG>>>>>>>>>>>>>>>>>>>>>                                 0.000019   Finder.4743
    

    What's interesting here is that I had manually deleted all of the empty com.bombich.ccc.* mountpoint folders before I tried to delete that file. Also, I'm not sure why Finder is looking for that Mobile Documents folder. In both of those access attempts, the error number is "2", which is "No such file or directory", and that matches up well with the text of the error dialog.

    OK, so I created the Mobile Documents folder and recreated that stale mountpoint. Finder kept looking deeper for something on that mountpoint. Playing along with its game, I finally determined that Finder is looking for this:

    11:00:50.751220  getattrlist                            /private/tmp/com.bombich.ccc.7LcYgG/private/tmp/com.bombich.ccc.7LcYgG/.Trashes/501      0.000011   Finder.6141
    

    Even after creating that folder, though, Finder still fails to put the item in the Trash. I tried with a large file, and it reported that the destination did not have enough free space (the Trash folder is on the startup disk, and the startup disk has hundreds of GB available). I tried with a smaller file, and got yet a third error (An unexpected error occurred, -8060). Clearly Finder is mishandling the unmounting of that Recovery HD volume.

    ...

    OK, I was able to consistently reproduce this only after rebooting. This seemed to do the trick:

    1. Restart the computer
    2. Open CCC
    3. Wait a moment (for CCC to unmount the Recovery HD volumes)
    4. Quit CCC
    5. Try to trash a file

    Once I was able to reproduce it consistently, I was able to test a fix. It looks like deleting those private mountpoint folders does the trick (yeah, it was those after all!). I'm going to call this a joint fail between CCC and Finder. CCC should have been cleaning up after itself, but whatever Finder was doing, that was definitely some buggy behavior.

    Let me know if you see this issue recur with the attached version of CCC. There's one other thing I can try if it does recur (mount the Recovery HD volumes read-only), but I'd rather not try that if it isn't necessary, because some other system services might get rankled.

    To replace your existing version:

    1. Move the older version aside (e.g. to the Trash or Desktop, but do not empty the Trash)
    2. Launch the new version and proceed to updated the scheduled tasks if prompted
    3. Discard the older version

    Thanks again,
    Mike

  4. 4 Posted by Ernst Mulder on 12 Nov, 2013 05:00 PM

    Ernst Mulder's Avatar

    Hello Mike,

    Thanks for your elaborate e-mail on this issue and for the fix! Brilliant.

    And thanks for sharing your investigation, it is a very interesting read.

    By the way, not only the Finder sees your newly created temporary mount point. When I start CCC at least 54 other processes notice the temp mount point with various queries. HardwareGrowler even reports on the mount/unmount of the Recovery HD.

    The Mavericks Finder querying /private/tmp/com.bombich.ccc.7LcYgG/private/tmp/com.bombich.ccc.<id>/.Trashes/501 does seem like a bug to me (looking for the trash folder in the wrong path, your mount point instead of /).

    I'll let you know if I encounter any more issues.

    By the way, I simply love CCC. Especially for its remote rsync capabilities. It's the only solution I could find to create a fully functional nightly copy of a running mail server. The biggest advantage over the more expensive Retrospect (which I use to make incremental backups of said copy of the mail server) is that when the backup is interrupted no data is lost.
    Retrospect scans, then erases and then copies, and sets privileges afterwards. Totally unacceptable imho.

    The only thing I would like to see added is the ability to edit scheduled tasks (instead of having to manually edit launchd plists when changing rsync exclusions for instance).

    Thanks,

    Ernst Mulder

    On 12 nov. 2013, at 17:32, Mike Bombich <[email blocked]> wrote:

  5. 5 Posted by Ernst Mulder on 12 Nov, 2013 05:05 PM

    Ernst Mulder's Avatar

    Mike,

    It's probably not really an issue, but the 3.5.4-b1 version does not delete previous com.bombich.ccc.XXXXXX folders still present in /private/tmp from previous runs of the older version.
    Couldn't this cause the Finder/Delete issue for some users even after installing and using the new version?

    Ernst.

    On 12 nov. 2013, at 17:32, Mike Bombich <[email blocked]> wrote:

  6. Support Staff 6 Posted by Mike Bombich on 12 Nov, 2013 05:10 PM

    Mike Bombich's Avatar

    HardwareGrowler even reports on the mount/unmount of the Recovery HD.

    Ah, I'd call that a configuration error on their part, unless it is their goal to alert the user to private mounts.

    The only thing I would like to see added is the ability to edit scheduled tasks

    Join the club :-) We're working on this for the next major release.

    the 3.5.4-b1 version does not delete previous com.bombich.ccc.XXXXXX folders still present in /private/tmp from previous runs of the older version.

    Correct, it only attempts to delete the mountpoint folder after it successfully unmounts the volume. Pasting "rmdir /tmp/com.bombich.*" into the Terminal will clear up the rest of them (as would rebooting).

    Couldn't this cause the Finder/Delete issue for some users even after installing and using the new version?

    I'm not sure, I couldn't seem to reproduce the issue once I had restarted the Finder once, I could only reproduce it after rebooting. And of course the old mountpoints are cleared out then...

    Mike

  7. 7 Posted by Ernst Mulder on 13 Nov, 2013 12:34 PM

    Ernst Mulder's Avatar

    Hello Mike,

    Quick note on my experiences with 3.5.4-b1 so far.

    Under certain circumstances version 3.5.4-b1 still leaves stale mount points behind in /private/tmp. Today I encountered the Finder/delete bug again and had multiple com.bombich.ccc.XXXXXX folders in /private/tmp.

    My guess is that when you quickly quit CCC after launching it it does not delete its mount points and in some cases does not even unmount its mounted Recovery HD partitions.

    Repeatable: Start CCC and quit it immediately whilst observing /private/tmp. The Recovery HD partitions are left mounted.
    Repeatable: Start CCC and quit it almost immediately whilst observing /private/tmp. After the Recovery HD partitions stale com.bombich.ccc.XXXXXX mount points are left behind.

    Ernst.

    On 12 nov. 2013, at 18:10, Mike Bombich <[email blocked]> wrote:

  8. Support Staff 8 Posted by Mike Bombich on 15 Nov, 2013 03:36 AM

    Mike Bombich's Avatar

    Hi Ernst:

    This scenario was a bit trickier, but I think I'm handling it as gracefully as possible in the attached build of CCC. If you quit immediately after opening CCC, the Recovery HD volumes will remain mounted. There's very little I can do about that without imposing a deliberate hang at application termination, and that would be messy. If you re-open CCC, though, it will now unmount any Recovery HD volumes that are mounted at the CCC-specific mountpoint. Also, upon quitting, CCC will remove any empty CCC-specific mountpoint folders in /tmp. Let me know how that works for you.

    Thanks,
    Mike

  9. Mike Bombich closed this discussion on 04 Dec, 2013 03:58 AM.

Comments are currently closed for this discussion. You can start a new one.

Keyboard shortcuts

Generic

? Show this help
ESC Blurs the current field

Comment Form

r Focus the comment reply box
^ + ↩ Submit the comment

You can use Command ⌘ instead of Control ^ on Mac