Cannot enter Time Machine hosted on ReadyNAS Pro from Lion

[sirozha]

After I upgraded to Lion, both of my Macs decided that they needed to wipe out the existing Time Machine backups hosted on the ReadyNAS (Pro Business) and make a brand new backup. First it was my wife’s Macbook Pro, which did so just a few days after I upgraded it to Lion (a month ago or so). It was reporting that it had to remove the older backups because it did not have enough space to make a new backup. Every time it would try to back up a few dozen gigabytes, it would say that it did not have enough space and would wipe out more older backups. Finally, it deleted every single backup, so when I would enter Time Machine, there was only one backup available. Since then, Time Machine made about 20 incremental backups, and I can enter Time Machine and see the backups.

Last night, on my Macbook Time Machine reported that it finished verifying the backup and needed to make a clean backup (or something to that effect). So, I plugged my Macbook into the network via an Ethernet cable (so that the backup would complete quicker than over Wi-Fi), and clicked on OK. By this morning Time Machine backed up about 100 GB. However, even though I can initiate an incremental backup, and it completes without any errors, I cannot enter Time Machine from my Macbook. When I try to “Enter Time Machine”, the Time Machine volume located on the ReadyNAS gets mounted, but I never get to the screen where I can see my first backup and incremental backups. I have never had this problem before. I have tried it over Wi-Fi and over my wired network - no luck either way.

Is there any way for me to get that functionality back, or should delete the sparse bundle and start over?

[mdgm]

What version of RAIDiator are you running?

[sirozha]

I am running 4.2.18

My wife’s Macbook Pro cannot “Enter Time Machine” either. I have restarted the ReadyNAS with the volume scan, which is now completed. Still no luck entering Time Machine. Time Machine backups seems to be working. Below is the log from my Macbook:

Code: Select all

8/31/11 10:11:21.824 PM com.apple.backupd: Attempting to mount network destination URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 10:11:27.237 PM com.apple.backupd: Mounted network destination at mountpoint: /Volumes/ReadyNAS using URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 10:11:48.615 PM com.apple.backupd: QUICKCHECK ONLY; FILESYSTEM CLEAN
8/31/11 10:11:51.557 PM com.apple.backupd: Disk image /Volumes/ReadyNAS/MB.sparsebundle mounted at: /Volumes/Time Machine Backups
8/31/11 10:11:56.714 PM mds: (Normal) DiskStore: Rebuilding index for /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:12:42.050 PM com.apple.backupd: Starting standard backup
8/31/11 10:12:42.068 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:12:58.637 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MB.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 10:12:59.881 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MB.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 10:13:01.070 PM com.apple.backupd: Disk image /Volumes/ReadyNAS/MB.sparsebundle mounted at: /Volumes/Time Machine Backups
8/31/11 10:13:01.075 PM com.apple.backupd: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:13:01.560 PM com.apple.backupd: malformed base path in GetVolumeEntry
8/31/11 10:13:01.560 PM com.apple.backupd: malformed base path in GetVolumeEntry
8/31/11 10:13:12.814 PM com.apple.backupd: 100.0 MB required (including padding), 253.87 GB available
8/31/11 10:13:12.817 PM com.apple.backupd: Waiting for index to be ready (100)
8/31/11 10:14:13.007 PM com.apple.backupd: Waiting for index to be ready (100)
8/31/11 10:18:16.085 PM com.apple.backupd: Starting standard backup
8/31/11 10:18:16.085 PM com.apple.backupd: Starting standard backup
8/31/11 10:18:16.085 PM com.apple.backupd: Starting standard backup
8/31/11 10:18:16.085 PM com.apple.backupd: Starting standard backup
8/31/11 10:18:16.085 PM com.apple.backupd: Starting standard backup
8/31/11 10:18:46.667 PM com.apple.backupd: Attempting to mount network destination URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 10:18:53.637 PM com.apple.backupd: Mounted network destination at mountpoint: /Volumes/ReadyNAS using URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 10:19:13.816 PM com.apple.backupd: QUICKCHECK ONLY; FILESYSTEM CLEAN
8/31/11 10:19:23.662 PM com.apple.backupd: Disk image /Volumes/ReadyNAS/MB.sparsebundle mounted at: /Volumes/Time Machine Backups
8/31/11 10:19:23.851 PM com.apple.backupd: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:19:24.894 PM com.apple.backupd: malformed base path in GetVolumeEntry
8/31/11 10:19:24.894 PM com.apple.backupd: malformed base path in GetVolumeEntry
8/31/11 10:19:26.002 PM com.apple.backupd: Event store UUIDs don't match for volume: Macintosh HD
8/31/11 10:19:27.198 PM com.apple.backupd: Deep event scan at path:/ reason:must scan subdirs|new event db|
8/31/11 10:26:12.451 PM com.apple.backupd: Finished scan
8/31/11 10:26:49.031 PM com.apple.backupd: 100.0 MB required (including padding), 253.87 GB available
8/31/11 10:29:25.659 PM com.apple.backupd: Copied 2721 files (14.5 MB) from volume Macintosh HD.
8/31/11 10:29:27.970 PM com.apple.backupd: 100.0 MB required (including padding), 253.87 GB available
8/31/11 10:29:56.274 PM com.apple.backupd: Copied 1130 files (414 KB) from volume Macintosh HD.
8/31/11 10:30:00.730 PM com.apple.backupd: Starting post-backup thinning
8/31/11 10:30:00.730 PM com.apple.backupd: No post-back up thinning needed: no expired backups exist
8/31/11 10:30:00.925 PM com.apple.backupd: Backup completed successfully.
8/31/11 10:30:00.962 PM com.apple.backupd: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb



[mdgm]

I don't have this issue, but I am running the beta firmware (don't know if this makes a difference).

Perhaps you should open a tech support case.

4.2.19, I believe is due for release soon. Once that is available you should update to that.

[sirozha]

After I tinkered some more with this, I was able to “Enter Time Machine”. Something is definitely wrong with it, though. For one thing, the “Oldest Backup” listed in the Time Machine applet in System Preferences is Today. 7:24 AM”, but when I enter Time Machine, the oldest backup is today at 10:35 PM. Additionally, a few times that I tried to “Enter Time Machine,” I got the following error message:

Code: Select all

An unexpected error occurred (error code -6584).


This same error message showed up on my wife’s Macbook Pro when I tried to “Enter Time Machine” from it.

Here’s the latest Time Machine log:

Code: Select all

8/31/11 10:30:00.962 PM com.apple.backupd: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:31:00.973 PM com.apple.backupd: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:33:00.998 PM com.apple.backupd: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:35:18.505 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:35:18.508 PM Finder: _CSBackupServerProxyCopyDestinationMountPoint returned backupdResultCode: 22
8/31/11 10:36:01.027 PM com.apple.backupd: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:37:06.148 PM com.apple.backupd: Starting standard backup
8/31/11 10:37:06.857 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:37:32.692 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MB.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 10:37:41.455 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MB.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 10:37:44.577 PM com.apple.backupd: Disk image /Volumes/ReadyNAS/MB.sparsebundle mounted at: /Volumes/Time Machine Backups
8/31/11 10:37:44.606 PM com.apple.backupd: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:37:44.975 PM com.apple.backupd: malformed base path in GetVolumeEntry
8/31/11 10:37:44.975 PM com.apple.backupd: malformed base path in GetVolumeEntry
8/31/11 10:37:54.873 PM com.apple.backupd: 100.0 MB required (including padding), 253.87 GB available
8/31/11 10:40:01.071 PM com.apple.backupd: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb
8/31/11 10:40:10.526 PM com.apple.backupd: Copied 1070 files (1.8 MB) from volume Macintosh HD.
8/31/11 10:40:14.608 PM com.apple.backupd: 100.0 MB required (including padding), 253.87 GB available
8/31/11 10:40:29.412 PM mdworker: FontImporter: Validation failed - "/Volumes/Time Machine Backups/Backups.backupdb/MB/2011-08-31-222956/Macintosh HD/Library/Fonts/Old Cambridge".
8/31/11 10:42:59.697 PM com.apple.backupd: Copied 694 files (501 KB) from volume Macintosh HD.
8/31/11 10:43:01.810 PM com.apple.backupd: Starting post-backup thinning
8/31/11 10:43:01.810 PM com.apple.backupd: No post-back up thinning needed: no expired backups exist
8/31/11 10:43:01.833 PM com.apple.backupd: Backup completed successfully.
8/31/11 10:43:18.489 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:43:35.286 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MB.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 10:43:36.549 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MB.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 10:43:37.783 PM com.apple.backupd: Disk image /Volumes/ReadyNAS/MB.sparsebundle mounted at: /Volumes/Time Machine Backups
8/31/11 10:44:16.014 PM com.apple.backupd: Stopping backup to allow backup destination disk to be unmounted or ejected.
8/31/11 10:44:33.642 PM com.apple.backupd: Backup failed because the destination disk was ejected or disconnected unexpectedly!
8/31/11 10:44:36.560 PM com.apple.backupd: Backup failed because the destination disk was ejected or disconnected unexpectedly!
8/31/11 10:44:47.990 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:44:48.005 PM Finder: _CSBackupServerProxyCopyDestinationMountPoint returned backupdResultCode: 22
8/31/11 10:46:58.848 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:46:58.850 PM Finder: _CSBackupServerProxyCopyDestinationMountPoint returned backupdResultCode: 22
8/31/11 10:52:31.404 PM com.apple.backupd: Network destination already mounted at: /Volumes/ReadyNAS
8/31/11 10:52:52.871 PM com.apple.backupd: QUICKCHECK ONLY; FILESYSTEM CLEAN
8/31/11 10:52:55.979 PM com.apple.backupd: Disk image /Volumes/ReadyNAS/MB.sparsebundle mounted at: /Volumes/Time Machine Backups



[sirozha]

Last night, I could no longer "Enter Time Machine" from my wife's Macbook Pro, either. Here's the log from that attempt on her Macbook Pro:

Code: Select all

8/31/11 9:47:01.975 PM com.apple.backupd: Attempting to mount network destination URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 9:47:07.218 PM com.apple.backupd: Mounted network destination at mountpoint: /Volumes/ReadyNAS using URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 9:47:24.980 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MBP.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 9:47:26.283 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MBP.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 9:47:27.571 PM com.apple.backupd: Failed to mount disk image: Error Domain=com.apple.backupd.ErrorDomain Code=31 "The operation couldn’t be completed. (com.apple.backupd.ErrorDomain error 31.)" UserInfo=0x10693ee20 {MessageParameters=(
    "/Volumes/ReadyNAS/MBP.sparsebundle"
)}
8/31/11 9:47:28.220 PM com.apple.backupd: Ejected Time Machine network volume.
8/31/11 9:47:28.221 PM com.apple.backupd: Waiting 60 seconds and trying again.
8/31/11 9:48:28.278 PM com.apple.backupd: Attempting to mount network destination URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 9:48:33.524 PM com.apple.backupd: Mounted network destination at mountpoint: /Volumes/ReadyNAS using URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 9:48:50.118 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MBP.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 9:48:51.426 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MBP.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 9:48:52.735 PM com.apple.backupd: Failed to mount disk image: Error Domain=com.apple.backupd.ErrorDomain Code=31 "The operation couldn’t be completed. (com.apple.backupd.ErrorDomain error 31.)" UserInfo=0x7fe2f3517e80 {MessageParameters=(
    "/Volumes/ReadyNAS/MBP.sparsebundle"
)}
8/31/11 9:48:53.250 PM com.apple.backupd: Ejected Time Machine network volume.
8/31/11 9:48:53.253 PM com.apple.backupd: Waiting 60 seconds and trying again.
8/31/11 9:49:53.306 PM com.apple.backupd: Attempting to mount network destination URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 9:49:57.393 PM com.apple.backupd: Mounted network destination at mountpoint: /Volumes/ReadyNAS using URL: afp://ReadyNAS@ProServer.local/ReadyNAS
8/31/11 9:50:13.963 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MBP.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 9:50:15.177 PM com.apple.backupd: Disk image already attached: /Volumes/ReadyNAS/MBP.sparsebundle, DIHLDiskImageAttach returned: 35
8/31/11 9:50:16.368 PM com.apple.backupd: Failed to mount disk image: Error Domain=com.apple.backupd.ErrorDomain Code=31 "The operation couldn’t be completed. (com.apple.backupd.ErrorDomain error 31.)" UserInfo=0x7fe2f351bcb0 {MessageParameters=(
    "/Volumes/ReadyNAS/MBP.sparsebundle"
)}
8/31/11 9:50:16.737 PM com.apple.backupd: Ejected Time Machine network volume.
8/31/11 9:50:16.742 PM com.apple.backupd: Giving up after 3 retries.
8/31/11 9:50:16.744 PM Finder: _CSBackupServerProxyCopyDestinationMountPoint returned backupdResultCode: 31



This morning, I moved my Macbook's sparsebundle from /c/.timemachine to another directory on the ReadyNAS and then tried to "Enter Time Machine". Strangely enough, I was able to enter it and see one backup (as of this morning) even though the sparsebundle was no longer in /c/.timemachine. Then I started a new Time Machine backup on my Macbook and saw the creation of the new sparsebundle inside /c/.timemachine on the ReadyNAS. After that, I tried to "Enter Time Machine" on my wife's Macbook Pro, and this time, I was able to enter it without any problem. Below is the log from her Macbook Pro.

Code: Select all

9/1/11 7:50:03.482 AM com.apple.backupd: Attempting to mount network destination URL: afp://ReadyNAS@ProServer.local/ReadyNAS
9/1/11 7:50:09.281 AM com.apple.backupd: Mounted network destination at mountpoint: /Volumes/ReadyNAS using URL: afp://ReadyNAS@ProServer.local/ReadyNAS
9/1/11 7:50:29.408 AM com.apple.backupd: QUICKCHECK ONLY; FILESYSTEM CLEAN
9/1/11 7:50:44.588 AM fseventsd: event logs in /Volumes/Time Machine Backups/.fseventsd out of sync with volume.  destroying old logs. (72742 13 72742)
9/1/11 7:50:45.514 AM com.apple.backupd: Disk image /Volumes/ReadyNAS/MBP.sparsebundle mounted at: /Volumes/Time Machine Backups
9/1/11 7:50:46.962 AM fseventsd: log dir: /Volumes/Time Machine Backups/.fseventsd getting new uuid: CD65D3E5-43B0-4AA9-8654-39ED98B6E941



As you can see, there is a message of logs being out of sync with volume, but also something about getting a new UUID. I am not really sure what it all means, though.

[sirozha]

I started and completed a new backup of my Macbook running Mac OS 10.7.1 to the ReadyNAS Pro Business running 4.2.18 after having moved the previous Time Machine backup sparse bundle to another location on my ReadyNAS Pro Business.

I can now “Enter Time Machine” backup, but strangely enough, I can enter it regardless of my network connection. Even if I disconnect from the network, I can still “Enter Time Machine.” Because in Lion, versions are somehow tied to Time Machine, I am beginning to think that being able to “Enter Time Machine” with the network connection down is a new feature in Lion. I can see Time Machine backups with the time stamps when I was at work with my Macbook, which means that my Macbook could not have made any real Time Machine backups at those times. I am not sure what those backups are. Perhaps in Lion, Time Machine continues to make backup snapshots locally and then transfers them to the sparsebundle on the NAS (or Time Capsule) next time it is on the same LAN as they are. Or, perhaps, those are the locally stored “versions” that are not transferred to the Time Machine sparsebundle and to which Time Machine has now access to. The reason I think these are versions is the fact that I can be in an application (like Mail) and after entering Time Machine (with the network connection down), I remain in Mail and can navigate through the timeline of “backups” and see a different number of messages in Mail, depending on a particular “backup”. All of this occurs with the network connection down.

I do not recall this being a possibility in previous versions of Mac OS X. Specifically, I do not recall being able to “Enter Time Machine” when not connected to the same LAN where my NAS was, and neither do I recall being able to remain in any application once having entered Time Machine. The only application available at that point was Finder-like interface, which allowed to restore a file from the Time Machine backup or delete a file completely from the Time Machine backup.

Could someone please shed some light on this new phenomenon? I would love to learn more about this new functionality of Time Machine. I would also like to know if the true Time Machine backups are stored on my ReadyNAS in the Time Machine sparsebundle in case I need to restore my Macbook after an HD failure. Because I can now “Enter Time Machine” without even being connected to the network, I do not know how to tell if there are real and usable (for restore) backups in the sparsebundle on my ReadyNAS.

[mdgm]

http://www.apple.com/macosx/whats-new/features.html#timemachine

[sirozha]

http://www.apple.com/macosx/whats-new/features.html#timemachine

Unfortunately, there is not much information there. It does hint to local backups, though.

[mdgm]

Yes. You can enable or disable local backups using the Terminal.

When you have the ReadyNAS share mounted to check how much space is used you could do e.g.

Code: Select all

cd /Volumes/ReadyNAS


Then do

Code: Select all

du -csh *.sparsebundle


4.2.19 (currently in beta) contains newer Netatalk code than 4.2.18. It may be worth considering upgrading to see if that helps.

[ninylund]

I just want to add that I also experience this behavior. The backup seems to work okay but I am unable to "Enter time machine", nothing happens when I click it.

[mdgm]

What version of RAIDiator are you running ninylund?

Welcome to the forum!

[longgy]

Same issue here. Time machine backups successful but cannot enter Time Machine. Using Lion on iMac
Radiator version is 4.2.19 on a RNDU2000

RESOLVED:
I went into finder and clicked on Time Machine Backups and browsed the Backups.backupdb folder.
I notice that I didn't have read access to the contents of Backups.backupdb, in my case the folder called 'iMac27'

Here is what I did:
Right-clicked on Backups.backupdb and selected 'Get Info'
Unlocked the folder padlock-->clicked on the gear--> click on "Apply to enclosed items"

It took some time to set the permission but I am now able to enter Time Machine.

[JustKJ]

I was having the same issue with my iMac. Backups run hourly with out a problem. Clicking the Time Machine App on the dock, caused the Time Machine drive on my ReadyNAS NV+ to mount, but the star field interface never appeared. I did what longgy did and it solved my problem. I changed my iMac's subfolder in the backups.backupdb fold to be Read Only rather than no access for Staff. bingo I can access it.

My System:
ReadyNAS NV+ w/ Firmware: RAIDiator 4.1.10 [1.00a043]
Early 2009 iMac w/ OSx 10.8.2 (12C60)