Project

General

Profile

Bug #4808

Time Machine Backup Failing after successfully creating new "fresh" backup.

Added by Kevin Hanson over 4 years ago. Updated over 3 years ago.

Status:
Closed: Cannot reproduce
Priority:
Nice to have
Assignee:
Josh Paetzel
Category:
OS
Target version:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

I got this error the other day, and it wouldn't let me resume backing up. It only gave me the option to create a new Time Machine backup. I thought it might be a one-time issue so I had it create a new fresh backup, deleting the old one. I came back from work today (4:55PM), and I see that now it won't back up, and it's giving me issues. However, my first backup actually finished up this morning, and it looks like it has had some recent successful backups before I got home, as the last success was at 3:18PM. I'm pasting the relevant logs below.

As it wouldn't let me manually initiate a backup, I went to my Time Machine preferences and clicked "Remove Disk" for the share I had on my FreeNAS box. I then re-added the same disk, using the same user / pass / encryption key I had before. It found the old backup, and it gave me the option to resume my backup. I chose "Use Existing Backup" and then the backup completed successfully. In terms of the logs below, I put a manual break in there between when I removed / re-added the disk.

Let me know if there's any more info I can submit to help resolve this bug. I know AFP / TIme Machine is always a pesky issue. Would love to help make it less pesky!!

-Kevin

4/14/14 3:15:47.081 PM com.apple.backupd21796: Starting automatic backup
4/14/14 3:15:47.082 PM com.apple.backupd21796: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/14/14 3:15:52.417 PM com.apple.backupd21796: Mounted network destination at mount point: /Volumes/Time Machine using URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/14/14 3:17:08.000 PM kernel0: hfs: mounted Time Machine Backups on device disk6s2
4/14/14 3:17:09.789 PM com.apple.backupd21796: Disk image /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle mounted at: /Volumes/Time Machine Backups
4/14/14 3:17:09.793 PM com.apple.backupd21796: Backing up to /dev/disk6s2: /Volumes/Time Machine Backups/Backups.backupdb
4/14/14 3:17:22.095 PM com.apple.backupd21796: Will copy (13.3 MB) from Macintosh HD
4/14/14 3:17:22.098 PM com.apple.backupd21796: Found 145 files (13.3 MB) needing backup
4/14/14 3:17:22.101 PM com.apple.backupd21796: 6.1 GB required (including padding), 7.39 TB available
4/14/14 3:17:46.315 PM com.apple.backupd21796: Copied 252 items (13.3 MB) from volume Macintosh HD. Linked 6894.
4/14/14 3:18:17.685 PM com.apple.backupd21796: Will copy (3 KB) from Macintosh HD
4/14/14 3:18:17.685 PM com.apple.backupd21796: Found 19 files (3 KB) needing backup
4/14/14 3:18:17.686 PM com.apple.backupd21796: 6.08 GB required (including padding), 7.39 TB available
4/14/14 3:18:20.551 PM com.apple.backupd21796: Copied 23 items (3 KB) from volume Macintosh HD. Linked 718.
4/14/14 3:18:29.032 PM com.apple.backupd21796: Created new backup: 2014-04-14-151828
4/14/14 3:18:29.248 PM com.apple.backupd21796: Starting post-backup thinning
4/14/14 3:18:29.248 PM com.apple.backupd21796: No post-backup thinning needed: no expired backups exist
4/14/14 3:18:29.391 PM com.apple.backupd21796: Backup completed successfully.
4/14/14 3:18:40.000 PM kernel0: hfs: unmount initiated on Time Machine Backups on device disk6s2
4/14/14 3:18:41.882 PM com.apple.backupd21796: Ejected Time Machine disk image: /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle
4/14/14 3:18:52.155 PM com.apple.backupd21796: Ejected Time Machine network volume.
4/14/14 4:18:59.342 PM com.apple.backupd22262: Starting automatic backup
4/14/14 4:18:59.343 PM com.apple.backupd22262: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/14/14 4:19:29.363 PM com.apple.backupd22262: NAConnectToServerSync failed with error: 64 for url: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/14/14 4:19:29.799 PM com.apple.backupd22262: Attempting to mount network destination using URL: afp:///Time%20Machine
4/14/14 4:19:30.369 PM com.apple.backupd22262: NAConnectToServerSync failed with error: 80 for url: afp:///Time%20Machine
4/14/14 4:19:30.370 PM com.apple.backupd22262: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
4/14/14 4:19:30.370 PM com.apple.backupd22262: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
4/14/14 4:19:30.373 PM com.apple.backupd22262: Backup failed with error 29: There was a problem authenticating with the destination.
4/14/14 4:54:33.995 PM com.apple.prefs.backup.remoteservice22502: assertion failed: 13C64: liblaunch.dylib + 25164 [38D1AB2C-A476-385F-8EA8-7AB604CA1F89]: 0x25
4/14/14 4:54:34.007 PM com.apple.prefs.backup.remoteservice22502: assertion failed: 13C64: liblaunch.dylib + 25164 [38D1AB2C-A476-385F-8EA8-7AB604CA1F89]: 0x25
4/14/14 4:54:34.237 PM com.apple.prefs.backup.remoteservice22502: Bogus event received by listener connection:
<error: 0x7fff790fab50> { count = 1, contents =
"XPCErrorDescription" => <string: 0x7fff790fae60> { length = 18, contents = "Connection invalid" }
}

[[[HERE'S WHERE I REMOVED / RE-ADDED THE SAME DISK]]]

4/14/14 5:10:29.634 PM UserEventAgent11: com.apple.backupd-auto launchd job disabled
4/14/14 5:11:50.584 PM UserEventAgent11: com.apple.backupd-auto launchd job enabled
4/14/14 5:11:57.111 PM com.apple.backupd22622: Starting manual backup
4/14/14 5:11:57.112 PM com.apple.backupd22622: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/14/14 5:11:57.359 PM com.apple.backupd22622: Mounted network destination at mount point: /Volumes/Time Machine-1 using URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/14/14 5:13:09.000 PM kernel0: hfs: mounted Time Machine Backups on device disk7s2
4/14/14 5:13:10.457 PM com.apple.backupd22622: Disk image /Volumes/Time Machine-1/Kevin’s MacBook Pro.sparsebundle mounted at: /Volumes/Time Machine Backups
4/14/14 5:13:10.468 PM com.apple.backupd22622: Backing up to /dev/disk7s2: /Volumes/Time Machine Backups/Backups.backupdb
4/14/14 5:13:23.003 PM com.apple.backupd22622: Will copy (37.7 MB) from Macintosh HD
4/14/14 5:13:23.006 PM com.apple.backupd22622: Found 440 files (37.7 MB) needing backup
4/14/14 5:13:23.009 PM com.apple.backupd22622: 6.13 GB required (including padding), 7.39 TB available
4/14/14 5:13:48.932 PM com.apple.backupd22622: Copied 624 items (37.7 MB) from volume Macintosh HD. Linked 5121.
4/14/14 5:14:19.774 PM com.apple.backupd22622: Will copy (3.8 MB) from Macintosh HD
4/14/14 5:14:19.775 PM com.apple.backupd22622: Found 14 files (3.8 MB) needing backup
4/14/14 5:14:19.775 PM com.apple.backupd22622: 6.09 GB required (including padding), 7.39 TB available
4/14/14 5:14:23.034 PM com.apple.backupd22622: Copied 18 items (3.8 MB) from volume Macintosh HD. Linked 631.
4/14/14 5:14:31.394 PM com.apple.backupd22622: Created new backup: 2014-04-14-171430
4/14/14 5:14:31.804 PM com.apple.backupd22622: Starting post-backup thinning
4/14/14 5:14:31.804 PM com.apple.backupd22622: No post-backup thinning needed: no expired backups exist
4/14/14 5:14:32.505 PM com.apple.backupd22622: Backup completed successfully.
4/14/14 5:14:43.000 PM kernel0: hfs: unmount initiated on Time Machine Backups on device disk7s2
4/14/14 5:14:44.277 PM com.apple.backupd22622: Ejected Time Machine disk image: /Volumes/Time Machine-1/Kevin’s MacBook Pro.sparsebundle
4/14/14 5:14:54.395 PM com.apple.backupd22622: Ejected Time Machine network volume.

History

#1 Updated by Jordan Hubbard over 4 years ago

  • Category set to 78
  • Assignee set to Josh Paetzel
  • Target version set to 79

I've heard a few reports of backups getting hosed when interrupted or otherwise not completing properly, and the "fix" being to start and stop the AFP service. Maybe the netatalk guys will receive enough similar reports that we can roll their fix into a future release.

#2 Updated by Kevin Hanson over 4 years ago

I think one of those reports you heard was my filing a similar bug, 4773: https://bugs.freenas.org/issues/4773

This one's a bit different... The error I get is different, and the logs show different stuff as well.

#3 Updated by Kevin Hanson over 4 years ago

750

An update on this... Yesterday I did what I described above, and then the Time Machine backups were working fine again. This morning, I got to my computer around 7:30AM, and I had a notification that the time machine backups failed. When I went into the preferences, I got the attached screenshot. The interesting thing is that it worked all night ever hour until 6:17AM, and then for whatever reason, it decided to fail on the next backup. I'm going to remove / re-add the Time Machine volume now, and I expect it to continue working. I will paste the logs below of both the failure as well as the success after removing / re-adding it. Let me know if there are any server-side logs that I can add to help with troubleshooting.

4/15/14 6:15:05.112 AM com.apple.backupd27807: Starting automatic backup
4/15/14 6:15:05.113 AM com.apple.backupd27807: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 6:15:05.703 AM com.apple.backupd27807: Mounted network destination at mount point: /Volumes/Time Machine using URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 6:16:23.000 AM kernel0: hfs: mounted Time Machine Backups on device disk6s2
4/15/14 6:16:24.310 AM com.apple.backupd27807: Disk image /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle mounted at: /Volumes/Time Machine Backups
4/15/14 6:16:24.313 AM com.apple.backupd27807: Backing up to /dev/disk6s2: /Volumes/Time Machine Backups/Backups.backupdb
4/15/14 6:16:37.421 AM com.apple.backupd27807: Will copy (8 MB) from Macintosh HD
4/15/14 6:16:37.423 AM com.apple.backupd27807: Found 114 files (8 MB) needing backup
4/15/14 6:16:37.428 AM com.apple.backupd27807: 6.09 GB required (including padding), 7.39 TB available
4/15/14 6:17:17.269 AM com.apple.backupd27807: Copied 196 items (8 MB) from volume Macintosh HD. Linked 3074.
4/15/14 6:17:29.613 AM com.apple.backupd27807: Will copy (6 KB) from Macintosh HD
4/15/14 6:17:29.614 AM com.apple.backupd27807: Found 27 files (6 KB) needing backup
4/15/14 6:17:29.614 AM com.apple.backupd27807: 6.08 GB required (including padding), 7.39 TB available
4/15/14 6:17:30.889 AM com.apple.backupd27807: Copied 31 items (6 KB) from volume Macintosh HD. Linked 599.
4/15/14 6:17:40.238 AM com.apple.backupd27807: Created new backup: 2014-04-15-061739
4/15/14 6:17:40.464 AM com.apple.backupd27807: Starting post-backup thinning
4/15/14 6:17:40.464 AM com.apple.backupd27807: No post-backup thinning needed: no expired backups exist
4/15/14 6:17:40.926 AM com.apple.backupd27807: Backup completed successfully.
4/15/14 6:17:51.000 AM kernel0: hfs: unmount initiated on Time Machine Backups on device disk6s2
4/15/14 6:17:53.036 AM com.apple.backupd27807: Ejected Time Machine disk image: /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle
4/15/14 6:18:03.243 AM com.apple.backupd27807: Ejected Time Machine network volume.
4/15/14 7:18:10.716 AM com.apple.backupd28216: Starting automatic backup
4/15/14 7:18:10.717 AM com.apple.backupd28216: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 7:18:40.738 AM com.apple.backupd28216: NAConnectToServerSync failed with error: 64 for url: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 7:18:41.189 AM com.apple.backupd28216: Attempting to mount network destination using URL: afp:///Time%20Machine
4/15/14 7:18:41.287 AM com.apple.backupd28216: NAConnectToServerSync failed with error: 80 for url: afp:///Time%20Machine
4/15/14 7:18:41.288 AM com.apple.backupd28216: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
4/15/14 7:18:41.288 AM com.apple.backupd28216: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
4/15/14 7:18:41.291 AM com.apple.backupd28216: Backup failed with error 29: There was a problem authenticating with the destination.
4/15/14 7:32:35.069 AM com.apple.backupd28305: Starting manual backup
4/15/14 7:32:35.070 AM com.apple.backupd28305: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 7:33:05.090 AM com.apple.backupd28305: NAConnectToServerSync failed with error: 64 for url: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 7:33:05.245 AM com.apple.backupd28305: Attempting to mount network destination using URL: afp:///Time%20Machine
4/15/14 7:33:05.819 AM com.apple.backupd28305: NAConnectToServerSync failed with error: 80 for url: afp:///Time%20Machine
4/15/14 7:33:05.819 AM com.apple.backupd28305: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
4/15/14 7:33:05.819 AM com.apple.backupd28305: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
4/15/14 7:33:05.822 AM com.apple.backupd28305: Backup failed with error 29: There was a problem authenticating with the destination.
4/15/14 7:33:10.816 AM com.apple.prefs.backup.remoteservice28332: assertion failed: 13C64: liblaunch.dylib + 25164 [38D1AB2C-A476-385F-8EA8-7AB604CA1F89]: 0x25
4/15/14 7:33:10.826 AM com.apple.prefs.backup.remoteservice28332: assertion failed: 13C64: liblaunch.dylib + 25164 [38D1AB2C-A476-385F-8EA8-7AB604CA1F89]: 0x25
4/15/14 7:33:11.053 AM com.apple.prefs.backup.remoteservice28332: Bogus event received by listener connection:
<error: 0x7fff790fab50> { count = 1, contents =
"XPCErrorDescription" => <string: 0x7fff790fae60> { length = 18, contents = "Connection invalid" }
}

{{NOW I REMOVED / RE-ADDED THE AFP SHARE}}

4/15/14 7:49:53.325 AM UserEventAgent11: com.apple.backupd-auto launchd job disabled
4/15/14 7:51:03.111 AM UserEventAgent11: com.apple.backupd-auto launchd job enabled
4/15/14 7:53:02.164 AM com.apple.backupd28556: Starting manual backup
4/15/14 7:53:02.164 AM com.apple.backupd28556: Attempting to mount network destination URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 8:05:32.565 AM com.apple.backupd28556: Mounted network destination at mount point: /Volumes/Time Machine-1 using URL: afp://kevinmacbookpro@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
4/15/14 8:06:34.000 AM kernel0: hfs: mounted Time Machine Backups on device disk7s2
4/15/14 8:06:35.215 AM com.apple.backupd28556: Disk image /Volumes/Time Machine-1/Kevin’s MacBook Pro.sparsebundle mounted at: /Volumes/Time Machine Backups
4/15/14 8:06:35.223 AM com.apple.backupd28556: Backing up to /dev/disk7s2: /Volumes/Time Machine Backups/Backups.backupdb
4/15/14 8:09:09.933 AM com.apple.backupd28556: Will copy (131.2 MB) from Macintosh HD
4/15/14 8:09:09.944 AM com.apple.backupd28556: Found 30643 files (464.1 MB) needing backup
4/15/14 8:09:09.980 AM com.apple.backupd28556: 6.64 GB required (including padding), 7.39 TB available
4/15/14 8:15:14.598 AM com.apple.backupd28556: Copied 30584 items (338.1 MB) from volume Macintosh HD. Linked 124198.
4/15/14 8:15:50.164 AM com.apple.backupd28556: Will copy (23.4 MB) from Macintosh HD
4/15/14 8:15:50.166 AM com.apple.backupd28556: Found 124 files (24.1 MB) needing backup
4/15/14 8:15:50.166 AM com.apple.backupd28556: 6.11 GB required (including padding), 7.39 TB available
4/15/14 8:15:59.111 AM com.apple.backupd28556: Copied 215 items (23 MB) from volume Macintosh HD. Linked 2242.
4/15/14 8:16:01.163 AM com.apple.backupd28556: Created new backup: 2014-04-15-081600
4/15/14 8:16:03.214 AM com.apple.backupd28556: Starting post-backup thinning
4/15/14 8:16:03.214 AM com.apple.backupd28556: No post-backup thinning needed: no expired backups exist
4/15/14 8:16:03.369 AM com.apple.backupd28556: Backup completed successfully.
4/15/14 8:16:13.000 AM kernel0: hfs: unmount initiated on Time Machine Backups on device disk7s2
4/15/14 8:16:15.272 AM com.apple.backupd28556: Ejected Time Machine disk image: /Volumes/Time Machine-1/Kevin’s MacBook Pro.sparsebundle
4/15/14 8:16:25.349 AM com.apple.backupd28556: Ejected Time Machine network volume.

#4 Updated by Kevin Hanson over 4 years ago

FYI this issue is now happening on both my MacBook Air as well as my MacBook Pro. For whatever reason, it isn't happening on my wife's MacBook Air - I did read something about having punctuation marks / spaces in the computer name, and hers is the only one that does not have any spaces / punctuation. Not sure if that could be an issue. In any case, I have plenty of logs, etc, and I'm happy to help work to solve this issue.

#5 Updated by Josh Paetzel over 4 years ago

  • Status changed from Unscreened to Screened

#6 Updated by Josh Paetzel over 4 years ago

4/15/14 7:18:41.288 AM com.apple.backupd28216: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.

That seems to be common to all the backup failed scenarios you are listing in this ticket. Just for kicks can you turn on anonymous access to the backup drive?

#7 Updated by Kevin Hanson over 4 years ago

Indeed I can... Only issue is that I'm traveling for about 10 days. When I get back, I'll turn on an anonymous access account and give it a try. BTW it turns out that if you wait 5 or 6 hours, or N amount of time, you don't necessarily need to remove / re-add the drive in Time Machine. You can force a manual backup. Sometimes it will work, sometimes it won't, but if it works, it then seems to work for some period of time before it stops working again. And oddly enough, as I mentioned, my wife's MacBook has not hit this issue yet, but my MacBook Air + MacBook Pro have.

#8 Updated by The m0nkey_ over 4 years ago

I've had the same problem. I assume you're resolving your FreeNAS box via mDNS? If so, then yes, I had errors this way. I found mounting the Time Machine volume either using it's FQDN or IP address then setting up TM gets around this issue, mDNS is out of the picture. Now my TM volume mounts every time.

#9 Updated by Kevin Hanson over 4 years ago

803

@Josh,

Okay so each machine has its own username / password combo. Today I got the error again with my MacBook Pro. I went in and changed my AFP settings as per the attached screenshot, giving guest access the default account that I use for my MBP. I went in and re-selected the disk, this time connecting w/ guest access, and it successfully found my old backup and asked if I wanted to continue using that. Of course, this would have worked even if I didn't turn on guest access. I guess now we just wait... If I get the error again, we know it is unrelated to authentication. If I don't... then... maybe it is authentication? Thanks for looking into this!

#10 Updated by Kevin Hanson over 4 years ago

Another update here... So on the machine with authentication OFF, I have not gotten an error since I last posted here, on May 4. Let's keep it going for a while, and I'll let you know if it does happen. However, on the box (my MacBook Air) w/ authentication ON, I did just get the error... Here are the logs... Does appear to be authentication related. I pasted up a bit so you can see that the previous backups completed successfully. Not sure why the final one decided it had an issue...

5/8/14 9:08:56.261 PM com.apple.backupd814: Starting automatic backup
5/8/14 9:08:56.262 PM com.apple.backupd814: Attempting to mount network destination URL: afp://kevinmacbookair@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
5/8/14 9:08:57.864 PM com.apple.backupd814: Mounted network destination at mount point: /Volumes/Time Machine using URL: afp://kevinmacbookair@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
5/8/14 9:10:02.469 PM com.apple.backupd814: Disk image /Volumes/Time Machine/Kevin’s MacBook Air.sparsebundle mounted at: /Volumes/Time Machine Backups
5/8/14 9:10:02.476 PM com.apple.backupd814: Backing up to /dev/disk2s2: /Volumes/Time Machine Backups/Backups.backupdb
5/8/14 9:10:12.410 PM com.apple.backupd814: Will copy (16.7 MB) from Macintosh HD
5/8/14 9:10:12.413 PM com.apple.backupd814: Found 295 files (16.7 MB) needing backup
5/8/14 9:10:12.425 PM com.apple.backupd814: 1.03 GB required (including padding), 7.25 TB available
5/8/14 9:10:29.257 PM com.apple.backupd814: Copied 349 items (16.7 MB) from volume Macintosh HD. Linked 986.
5/8/14 9:10:42.903 PM com.apple.backupd814: Will copy (87 KB) from Macintosh HD
5/8/14 9:10:42.904 PM com.apple.backupd814: Found 15 files (87 KB) needing backup
5/8/14 9:10:42.905 PM com.apple.backupd814: 1.01 GB required (including padding), 7.25 TB available
5/8/14 9:10:43.682 PM com.apple.backupd814: Copied 19 items (87 KB) from volume Macintosh HD. Linked 182.
5/8/14 9:10:49.139 PM com.apple.backupd814: Created new backup: 2014-05-08-211048
5/8/14 9:10:49.359 PM com.apple.backupd814: Starting post-backup thinning
5/8/14 9:10:49.359 PM com.apple.backupd814: No post-backup thinning needed: no expired backups exist
5/8/14 9:10:49.511 PM com.apple.backupd814: Backup completed successfully.
5/8/14 9:10:52.845 PM com.apple.backupd814: Ejected Time Machine disk image: /Volumes/Time Machine/Kevin’s MacBook Air.sparsebundle
5/8/14 9:10:52.967 PM com.apple.backupd814: Ejected Time Machine network volume.
5/8/14 10:11:19.280 PM com.apple.backupd1039: Starting automatic backup
5/8/14 10:11:19.282 PM com.apple.backupd1039: Attempting to mount network destination URL: afp://kevinmacbookair@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
5/8/14 10:11:49.354 PM com.apple.backupd1039: NAConnectToServerSync failed with error: 64 for url: afp://kevinmacbookair@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
5/8/14 10:11:49.747 PM com.apple.backupd1039: Attempting to mount network destination using URL: afp:///Time%20Machine
5/8/14 10:11:50.328 PM com.apple.backupd1039: NAConnectToServerSync failed with error: 80 for url: afp:///Time%20Machine
5/8/14 10:11:50.328 PM com.apple.backupd1039: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
5/8/14 10:11:50.328 PM com.apple.backupd1039: Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user.
5/8/14 10:11:50.350 PM com.apple.backupd1039: Backup failed with error 29: There was a problem authenticating with the destination.

#11 Updated by Kevin Hanson over 4 years ago

I won't re-paste the recent logs here, but could this issue be related to https://bugs.freenas.org/issues/4930 ?

#12 Updated by Kevin Hanson over 4 years ago

FYI ~ this error has re-occurred last night, even with authentication off.

#13 Updated by Kevin Hanson over 4 years ago

Happened again today. Logs below:

(the reason why it looks like it's going to succeed the last time is because I went onto my FreeNAS box and disabled / re-enabled AFP). That does the trick.

6/2/14 9:31:37.587 AM com.apple.backupd7511: Ejected Time Machine network volume.
6/2/14 9:31:37.596 AM com.apple.backupd7511: Waiting 60 seconds and trying again.
6/2/14 9:32:42.089 AM com.apple.backupd7511: Attempting to mount network destination URL: afp://;AUTH=No%20User%20Authent@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
6/2/14 9:32:42.263 AM com.apple.backupd7511: Mounted network destination at mount point: /Volumes/Time Machine using URL: afp://;AUTH=No%20User%20Authent@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
6/2/14 9:33:12.769 AM com.apple.backupd7511: Disk image already attached: /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle, DIHLDiskImageAttach returned: 35
6/2/14 9:33:14.160 AM com.apple.backupd7511: 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=0x7f8dd31014f0 {MessageParameters=(
"/Volumes/Time Machine/Kevin\U2019s MacBook Pro.sparsebundle"
)}
6/2/14 9:33:14.220 AM com.apple.backupd7511: Ejected Time Machine network volume.
6/2/14 9:33:14.225 AM com.apple.backupd7511: Waiting 60 seconds and trying again.
6/2/14 9:34:18.949 AM com.apple.backupd7511: Attempting to mount network destination URL: afp://;AUTH=No%20User%20Authent@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
6/2/14 9:34:20.508 AM com.apple.backupd7511: Mounted network destination at mount point: /Volumes/Time Machine using URL: afp://;AUTH=No%20User%20Authent@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
6/2/14 9:34:50.405 AM com.apple.backupd7511: Disk image already attached: /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle, DIHLDiskImageAttach returned: 35
6/2/14 9:34:51.765 AM com.apple.backupd7511: 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=0x7f8dd0c0dda0 {MessageParameters=(
"/Volumes/Time Machine/Kevin\U2019s MacBook Pro.sparsebundle"
)}
6/2/14 9:34:51.861 AM com.apple.backupd7511: Ejected Time Machine network volume.
6/2/14 9:34:51.865 AM com.apple.backupd7511: Giving up after 3 retries.
6/2/14 9:34:51.870 AM com.apple.backupd7511: Backup failed with error 31: 31
6/2/14 9:35:20.902 AM com.apple.backupd7511: Starting manual backup
6/2/14 9:35:20.902 AM com.apple.backupd7511: Attempting to mount network destination URL: afp://;AUTH=No%20User%20Authent@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
6/2/14 9:35:21.210 AM com.apple.backupd7511: Mounted network destination at mount point: /Volumes/Time Machine using URL: afp://;AUTH=No%20User%20Authent@Hanson-NAS._afpovertcp._tcp.local/Time%20Machine
6/2/14 9:36:33.520 AM com.apple.backupd7511: Disk image /Volumes/Time Machine/Kevin’s MacBook Pro.sparsebundle mounted at: /Volumes/Time Machine Backups
6/2/14 9:36:33.522 AM com.apple.backupd7511: Backing up to /dev/disk4s2: /Volumes/Time Machine Backups/Backups.backupdb

#14 Updated by Josh Paetzel over 4 years ago

We should proxy this into a netatalk ticket, I see no reason to suspect that FreeNAS has anything to do with this problem.

Can you create a netatalk ticket and put the link into this ticket just so we can keep track of it?

#15 Updated by Jordan Hubbard over 4 years ago

  • Target version changed from 79 to 103

#16 Updated by Chris Bellers over 4 years ago

I'd like to chime in that I found this report while searching for a solution to the same problem, which I'm also experiencing.

Freenas 9.2.1.5
OS X 10.9.3

Time Machine will back up for a couple hours, then backups randomly start failing with that error "Authentication error (80) - the correct user or password info may not exist in the System.keychain or the server may no longer allow access for this user."

For me, manually remounting the disk via finder and kicking off the backup again will make it work for a couple hours.

#17 Updated by Chris Bellers over 4 years ago

I have a workaround/fix for this issue: I went into the afpd options on the freenas host and increased the maximum connections from the default of 50 up to the maximum of 1000. It's been 4 days and none of the three macs in the house have exhibited the error behavior. Nothing but smooth backups here since I made the change.

#18 Updated by Kevin Hanson over 4 years ago

Filed a Netatalk ticket here: https://sourceforge.net/p/netatalk/bugs/573/

#19 Updated by John V over 4 years ago

Kevin Hanson wrote:

Filed a Netatalk ticket here: https://sourceforge.net/p/netatalk/bugs/573/

Have either one of you guys experienced this with an older version of FreeNAS? I'm still on 9.2.1.2 and haven't experienced any issues with a couple of Macs backing up to it.
Is it possible to downgrade your FreeNAS version?

I only came across this because I was thinking about upgrading to a newer version of FreeNAS but figured I should see what's broken first :D

#20 Updated by Jordan Hubbard over 4 years ago

  • Status changed from Screened to Closed: Cannot reproduce

Not seeing this in any instance of 9.2.1.6

#21 Updated by Abscond 784 over 4 years ago

Chris Bellers wrote:

I have a workaround/fix for this issue: I went into the afpd options on the freenas host and increased the maximum connections from the default of 50 up to the maximum of 1000. It's been 4 days and none of the three macs in the house have exhibited the error behavior. Nothing but smooth backups here since I made the change.

I'm still seeing this bug in FreeNAS 9.2.16 (or in Netatalk 3.1.2, if that's where it actually is), and unfortunately the workaround mentioned above doesn't solve the problem for me. I also have 4 Macs trying to back up.

#22 Updated by Jordan Hubbard about 4 years ago

  • Target version changed from 103 to 9.3-RELEASE

#23 Updated by Colin Borys over 3 years ago

Same problem for me on 9.3-RELEASE. Fix for me was to go in and hack with the keychain on the affected mac. Seems like it wants the password for afp:///Time Machine but the one stored in the keychain on the mac is for afp://user@host._afpovertcp._tcp.local/Time Machine.

Let's say you called your freenas box 'freenas'. Open up the 'keychain accesss' app on your mac and search for freenas. You'll see an entry for freenas._afpovertcp._tcp.local. You should be able to copy it, paste it, then edit the 'Name' and 'Where' inputs to point to freenas.local

For me, I found keychain a pain to edit. Might be due to how keychain syncs with apple so that your keys can be used cross device. In any case, in the end I 'copied', then edited the original, then pasted.

My keychain has entries for both freenas._afpovertcp._tcp.local and freenas.local. Been a week now and no problems.

#24 Updated by Chuck Schweizer over 3 years ago

I am seeing this issue with mdns also. Found this bug report (https://bugs.pcbsd.org/issues/7133) that says to do the following to setup time machine and it seems to be working much better now.

  sudo tmutil setdestination -p afp://USERID@freenas.local/FreeNAS\ TimeMachine

Also available in: Atom PDF