Time machine over AFP problem: permission denied

[vladak]

Hi all, this is my first post here so please bear with me.

Generic problem statement: I am unable to setup Time machine backups from older Macbook Pro using AFP to FreeNAS.

This is a fresh install of FreeNAS 11.3-U1. The Macbook Pro (mid 2009) is running macOS El Capitan 10.11.6 (the highest the machine can run AFAIK). This macOS version does not seem to be willing to recognize SMB Time machine share (meaning in Time machine preferences when adding new backup target drive) however does recognize AFP Time machine share. That's why I am trying to setup AFP for Time machine. For references, with my other machine, Mac mini running macOS High Sierra 10.13.6, the SMB based Time machine using the same NAS works just fine.

The setup on the FreeNAS side was done like this:

1. create a data set, sharing left at Generic
2. changed Permissions on the data set to the user who will be running the backup (ticked Apply permissions recursively for a good measure)
3. add AFP share, ticked Time machine

When I try to add this AFP share on the Macbook, it will see it. There is clearly some network traffic and I/O going on for a while (while it says 'Connecting to nas' where nas is the hostname of the NAS) until it ends with an error: The operation couldn't be completed (OSStatus error 2).

Looking in the /var/log/afp.log on the NAS I see this:

Code:

Jun 07 00:02:38.472174 cnid_dbd[19260] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:38.475244 cnid_dbd[19261] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:39.541749 cnid_dbd[19262] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:40.608698 cnid_dbd[19263] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:50.077723 cnid_dbd[19264] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:51.100220 cnid_dbd[19265] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:52.161919 cnid_dbd[19266] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied
Jun 07 00:02:53.228719 cnid_dbd[19267] {db_param.c:119} (error:CNID): error opening /mnt/uloziste/macbackup/m3/.AppleDB/db_param: Permission denied

This correlates with the attempts to set up the Time machine backup drive. It seems that with each attempt multiple of these log entries are produced.

Code:

% cnid_dbd -v
cnid_dbd (Netatalk 3.1.12)

It is nice that the log entries contain source code line information so looking at the source code https://github.com/Netatalk/Netatalk/blob/branch-netatalk-3-1/etc/cnid_dbd/db_param.c#L119

Code:

   110        if ((fp = fopen(pfn, "r")) == NULL) {
   111            if (errno == ENOENT) {
   112                if (strlen(params.usock_file) == 0) {
   113                    LOG(log_error, logtype_cnid, "default usock filename too long");
   114                    return NULL;
   115                } else {
   116                    return &params;
   117                }
   118            } else {
   119                LOG(log_error, logtype_cnid, "error opening %s: %s", pfn, strerror(errno));
   120                return NULL;
   121            }
   122        }

It failed to read a file (rather than create). I don't see the file around any more though:

Code:

% sudo ls -al /mnt/uloziste/macbackup/m3/.AppleDB/
total 134
drwxr-xr-x  2 katka  katka         6 Jun  7 00:12 .
drwxr-xr-x  3 katka  katka         6 Jun  6 23:31 ..
-rw-r--r--  1 katka  katka    163840 Jun  6 23:01 cnid2.db
-rw-r--r--  1 katka  katka        27 Jun  6 22:48 db_errlog
-rw-r--r--  1 katka  katka         0 Jun  6 22:48 lock
-rw-r-----  1 katka  katka  10485760 Jun  6 23:01 log.0000000001

The user should be able to create a file in this directory just fine, at least according to the Unix permissions. As I mentioned above the AFP share was created with default settings (modulo the Time machine). Looking at the advanced settings of the AFP share, I can see the AFP3 Unix privs setting ticked. Tried changing it to no avail.

Anyone has any idea before I start dtracing around ?

I don't think hardware information is relevant in this case however if you want to see my rig look here: https://pcpartpicker.com/b/8hgJ7P

 

[vladak]

The workaround is to use different backend (http://netatalk.sourceforge.net/3.1/htmldocs/configuration.html#CNID-backends). In my case I used tdb which should work fine given this share is used by single computer. I added cnid scheme = tdb as Auxiliary parameter for the share and the Time machine backup went through.

Code:

% less /usr/local/etc/afp.conf
[Global]
        uam list = uams_dhx.so uams_dhx2.so
        max connections = 50
        mimic model = RackMac
        afpstats = yes
        vol dbnest = yes
        map acls = rights
        chmod request = preserve
        log file = /var/log/afp.log
        log level = default:info

[m3]
        path = /mnt/uloziste/macbackup/m3
        time machine = yes
        cnid dev = no
        file perm = 647
        directory perm = 757
        umask = 000
        veto files = .windows/.mac/
        cnid scheme = tdb