Strange Time Capsule problem.

Whitehill

Registered
Well, strange to me. See the log below. This has been happening for about a week. The TM backup at 9PM finishes normally. Something (?) remounts the TC at 9:30PM. The TM backup at 10PM fails because the TC is already mounted.

I do have scheduled at 9:30PM M-F a SuperDuper! backup to a different device, a USB external - it completes with no problem. I have a feeling that SD is the culprit, just because of the timing. One time, with the USB disk ejected, I started SD and it told it could not find the Time Capsule?!

I just changed the SD schedule to skip tonight's backup. I'll see what happens when I get in tom'w morning.

Is there somewhere else to look to try to discover what's going on?


9/5/12 9:06:28.550 PM com.apple.backupd[42126]: Backup completed successfully.
9/5/12 9:06:31.617 PM com.apple.backupd[42126]: Ejected Time Machine disk image: /Volumes/Data/server.sparsebundle
9/5/12 9:06:31.882 PM com.apple.backupd[42126]: Ejected Time Machine network volume.
9/5/12 9:06:32.000 PM kernel[0]: AFP_VFS afpfs_unmount: /Volumes/Data, flags 0, pid 42156
9/5/12 9:06:32.000 PM kernel[0]: AFP_VFS afpfs_unmount : We are the last mnt/sbmnt using volume /Volumes/Data 0xffffff80f53f7008
9/5/12 9:06:32.000 PM kernel[0]: AFP_VFS afpfs_unmount : We are the last volume using socket /Volumes/Data 0xffffff80f53f7008
9/5/12 9:06:32.000 PM kernel[0]: AFP_VFS afpfs_unmount : afpfs_DoReconnect sent signal for unmount to proceed
9/5/12 9:30:06.000 PM kernel[0]: AFP_VFS afpfs_mount: /Volumes/Data, pid 42370
9/5/12 9:30:06.000 PM kernel[0]: AFP_VFS afpfs_mount : succeeded on volume 0xffffff80f5437008 /Volumes/Data (error = 0, retval = 0)
9/5/12 10:05:16.288 PM com.apple.backupd[43034]: Starting automatic backup
9/5/12 10:05:16.964 PM com.apple.backupd[43034]: Attempting to mount network destination URL: afp://xxxxxxx%20xxxxxxx;AUTH=SRP@My%20Time%20Capsule._afpovertcp._tcp.local/Data
9/5/12 10:05:17.457 PM com.apple.backupd[43034]: Mounted network destination at mount point: /Volumes/Data-1 using URL: afp://xxxxxxx%20xxxxxxx;AUTH=SRP@My%20Time%20Capsule._afpovertcp._tcp.local/Data
9/5/12 10:05:17.000 PM kernel[0]: ASP_TCP asp_tcp_usr_control: invalid kernelUseCount 0
9/5/12 10:05:17.000 PM kernel[0]: AFP_VFS afpfs_mount: /Volumes/Data-1, pid 43036
9/5/12 10:05:17.000 PM kernel[0]: AFP_VFS afpfs_mount : succeeded on volume 0xffffff80f5144008 /Volumes/Data-1 (error = 0, retval = 0)
9/5/12 10:05:31.139 PM com.apple.backupd[43034]: Disk image already attached: /Volumes/Data-1/server.sparsebundle, DIHLDiskImageAttach returned: 35
9/5/12 10:05:32.359 PM com.apple.backupd[43034]: 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=0x7fd89a026900 {MessageParameters=(
"/Volumes/Data-1/server.sparsebundle"
)}
 

Whitehill

Registered
SuperDuper! is the miscreant. Skipping last evening's SD backup allowed TM backups to proceed as expected. Next experiment ...

I deleted the SD scheduled backup ... and then reentered it.
 

Satcomer

In Geostationary Orbit
Thanks for the update. Good detective work!
 

Whitehill

Registered
Problem gone!

I will notify the developers that using SD for a one-time copy leaves the overall schedule in a weird state. I guess I didn't mention that.

I had a good TM disk on one of my machines and used SD on the problem machine to copy the backups to TC. That worked fine and TM on the other machine has been using it happily ever since.
 
Top