Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

Background info:

I have an Ubuntu 12.04 server on which I have Samba (v3.6.3) and Netatalk (v3.1.0) installed.

I use TimeMachine on my Mac to backup to the Ubuntu server over AFP provided by Netatalk.

Once or twice every 24 hours, my Mac tells me that it failed to backup to the server, informing me of the following:

Time Machine couldn’t complete the backup to “Server1”.

The network backup disk could not be accessed because there was a problem with the network username or password. You may need to re-select the backup disk and enter the correct username and password.

If I try the backup again straight away after the failed message, the backup completed successfully and continues to for some time after.

This issue arose since moving from an iMac (connected via gigabit ethernet) to a MacBook Pro (connected via WiFi through an Apple AirPort express, also tested through a Linksys WAG320N router). I think the key factor here is the change from a reliable gigabit connection to an unpredictable WiFi connection, but this does not affect any other services, such as SSH, HTTP, Samba, etc. and should not affect this either.

None of the other Macs that I have experience this issue (all on gigabit ethernet and running OS X 10.9.1).

I have witnessed connections to AFP shared on the server fail to connect in the same way, so this proves the issue is not isolated to TimeMachine, but more AFP/Netatalk authenticaiton.

What I have tried:

I've spent a good few hours today trying to get the bottom of the issue. Up to now, I have the following:

To begin with, the Mac logs the following:

25/01/2014 10:56:14.058 com.apple.backupd[59667]: Starting manual backup
25/01/2014 10:56:14.058 com.apple.backupd[59667]: Attempting to mount network destination URL: afp://joe@Server1._afpovertcp._tcp.local/TimeMachine
25/01/2014 10:56:14.340 com.apple.backupd[59667]: NAConnectToServerSync failed with error: 64 for url: afp://joe@Server1._afpovertcp._tcp.local/TimeMachine
25/01/2014 10:56:14.461 com.apple.backupd[59667]: Attempting to mount network destination using URL: afp://joe@Server1.local/TimeMachine
25/01/2014 10:56:16.989 com.apple.backupd[59667]: NAConnectToServerSync failed with error: 80 for url: afp://joe@Server1.local/TimeMachine
25/01/2014 10:56:16.989 com.apple.backupd[59667]: 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.
25/01/2014 10:56:16.989 com.apple.backupd[59667]: 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.
25/01/2014 10:56:16.992 com.apple.backupd[59667]: Backup failed with error 29: There was a problem authenticating with the destination.

I've deleted the server's TimeMachine credential entry from the Mac's System.keychain and allowed System Preferences.app to create a new one in the Keychain by re-creating the TimeMachine disk and re-entering the username and password to use for backups. I also verified that the new credential entry contains the correct username and password afterwards.

I've recreated my Mac's keychain items.

I've reinstalled Mac OS X Mavericks 10.9.1 and opted to not migrate data from my server's TimeMachine backups, in order to rule out any messed up .plist files, however the issue still occurs.

After enabling all debug logging in /etc/afp.conf on the server, I get:

Jan 25 10:56:10.193750 afpd[29908] {afp_dsi.c:610} (D5:AFPDaemon): <== Start AFP command: AFP_LOGINCONT
Jan 25 10:56:10.195767 afpd[29908] {uams_dhx2_pam.c:214} (I:UAMS): PAM DHX2: PAM Success
Jan 25 10:56:12.665479 afpd[29908] {uams_dhx2_pam.c:666} (I:UAMS): DHX2: PAM_Error: Authentication failure

So, next I turned to /var/log/auth.log:

Jan 25 10:56:10 Server1 afpd: pam_unix(netatalk:auth): authentication failure; logname= uid=0 euid=0 tty=afpd ruser=joe rhost=<my_mac's_rdns_ptr>  user=joe
Jan 25 10:56:10 Server1 afpd: pam_winbind(netatalk:auth): getting password (0x00000388)
Jan 25 10:56:10 Server1 afpd: pam_winbind(netatalk:auth): pam_get_item returned a password
Jan 25 10:56:10 Server1 afpd: pam_winbind(netatalk:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_USER_UNKNOWN (10), NTSTATUS: NT_STATUS_NO_SUCH_USER, Error message was: No such user

So, it looks like pam_winbind is declining the authentication attempt, however the user is indeed valid (it's the primary account on the server and I'm logged it via SSH using it now).

I decided to enable debug logging for pam_winbind by adding the following to /etc/security/pam_winbind.conf:

[global]

# turn on debugging
debug = yes

# turn on extended PAM state debugging
debug_state = yes

Which gives me the following in /var/log/auth.log:

Jan 25 13:25:15 Server1 afpd[446]: pam_unix(netatalk:auth): authentication failure; logname= uid=0 euid=0 tty=afpd ruser=joe rhost=<my_mac's_rdns_ptr>  user=joe
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] ENTER: pam_sm_authenticate (flags: 0x0000)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_SERVICE) = "netatalk" (0x206c1e0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_USER) = "joe" (0x206c200)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_TTY) = "afpd" (0x20792a0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_RHOST) = "<my_mac's_rdns_ptr>" (0x206fdb0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_RUSER) = "joe" (0x20792c0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_AUTHTOK) = 0x2079370
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_CONV) = 0x206c220
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): getting password (0x00001389)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): pam_get_item returned a password
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): Verify user 'joe'
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): PAM config: krb5_ccache_type 'FILE'
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): enabling krb5 login flag
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): enabling cached login flag
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): enabling request for a FILE krb5 ccache
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): request wbcLogonUser failed: WBC_ERR_AUTH_ERROR, PAM error: PAM_USER_UNKNOWN (10), NTSTATUS: NT_STATUS_NO_SUCH_USER, Error message was: No such user
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): user 'joe' not found
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] LEAVE: pam_sm_authenticate returning 10 (PAM_USER_UNKNOWN)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_SERVICE) = "netatalk" (0x206c1e0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_USER) = "joe" (0x206c200)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_TTY) = "afpd" (0x20792a0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_RHOST) = "<my_mac's_rdns_ptr>" (0x206fdb0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_RUSER) = "joe" (0x20792c0)
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_AUTHTOK) = 0x2079370
Jan 25 13:25:15 Server1 afpd[446]: pam_winbind(netatalk:auth): [pamh: 0x206c060] STATE: ITEM(PAM_CONV) = 0x206c220

I must point out that I have no strict requirement to use winbind for auth, however I believe that my system has pulled it in when selecting Samba Windows File Server from the tasksel screen when installing the system. Hence, Netatalk is consulting winbind as it should, I guess...

Where next?

Now, I've hit a bit of ceiling with my troubleshooting. I've tried Ubuntu and Samba IRC rooms, but no joy there. I may resort to posting to Ubuntu forums, but my searches of the so far have not shed any light on this issue.

Does anyone know why authentication is failing in this way?

UPDATE I checked to see if anything depended on pam_winbind and as there was nothing depending on it, I decided to remove it from the equation with sudo apt-get auto remove --purge winbind.

Since then, I still continue to see random connection issues, still with the following message logged on the Mac:

Backup failed with error 29: There was a problem authenticating with the destination.

That rules pam_winbind out and now leaves Netatalk <--> PAM. I suppose the key factor here is that this only happens over a WiFi link, and not for the Macs which are connected via ethernet. I've updated the title accordingly.

Slightly related issue, but on a ReadyNAS: http://www.readynas.com/forum/viewtopic.php?f=17&t=46622

I'm not sure what to try next so anyone's input on this would be greatly appreciated.

share|improve this question
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Browse other questions tagged or ask your own question.