#594 AFP_DELETE -> AFPERR_ACCESS

[Robert]

Hi,

I have an Apple time capsule mounted via cifs on my raspberry, which works fine. Locally I can add and remove files as expected. Mount point is /mnt/timemachine

NOW, when accessing /mnt/timemachine via Netatalk (3.1.7) and Afp from my MacBook: I can log in fine and also create files, but I cannot DELETE files. The OSX (Yosemite) message states that I have no permissions to do so.

The afp log file says "AFP_DELETE -> AFPERR_ACCESS" but not why. Again deleting the same file locally as the same afp user works without a problem.

The relevant part of the afp log:

Apr 19 20:37:07.449950 afpd[17568] {afp_dsi.c:624} (debug:AFPDaemon): <== Start AFP command: AFP_DELETE
Apr 19 20:37:07.450382 afpd[17568] {directory.c:566} (debug:AFPDaemon): dirlookup(did: 2): START
Apr 19 20:37:07.450810 afpd[17568] {directory.c:716} (debug:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/mnt/timecapsule"
Apr 19 20:37:07.451250 afpd[17568] {directory.c:1321} (debug:AFPDaemon): movecwd(to: did: 2, "/mnt/timecapsule")
Apr 19 20:37:07.453300 afpd[17568] {directory.c:1227} (debug:AFPDaemon): came('/mnt/timecapsule'): {file: 'asr.txt'}
Apr 19 20:37:07.453940 afpd[17568] {directory.c:1292} (debug:AFPDaemon): cname('/mnt/timecapsule') {end: curdir:'/mnt/timecapsule', path:'asr.txt'}
Apr 19 20:37:07.454312 afpd[17568] {file.c:1557} (debug:AFPDaemon): deletefile('asr.txt')
Apr 19 20:37:07.454661 afpd[17568] {ad_open.c:1849} (debug:ad): ad_open("/mnt/timecapsule/asr.txt", HF|OF|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.455014 afpd[17568] {ad_open.c:992} (debug:ad): ad_open_df("/mnt/timecapsule/asr.txt", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.457414 afpd[17568] {ad_open.c:1058} (debug:ad): ad_open_df("/mnt/timecapsule/asr.txt", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.458465 afpd[17568] {ad_open.c:1205} (debug:ad): ad_open_hf_ea("/mnt/timecapsule/asr.txt", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.460510 afpd[17568] {ad_open.c:754} (debug:ad): ad_header_read_ea: No data available
Apr 19 20:37:07.461116 afpd[17568] {ad_open.c:1240} (debug:ad): ad_open_hf_ea("asr.txt"): can't read metadata EA
Apr 19 20:37:07.461627 afpd[17568] {ad_open.c:1279} (debug:ad): ad_open_hf_ea("/mnt/timecapsule/asr.txt", DF|HF|OF|SHRMD|O_RDONLY): END: -1 [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.462119 afpd[17568] {ad_flush.c:423} (debug:ad): ad_close(DF): BEGIN: {d: 1, m: 0, r: 0} [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.463231 afpd[17568] {ad_flush.c:486} (debug:ad): ad_close(DF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.463627 afpd[17568] {ad_open.c:1912} (debug:ad): ad_open("/mnt/timecapsule/asr.txt"): END: -1 {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.463989 afpd[17568] {ad_open.c:1849} (debug:ad): ad_open("/mnt/timecapsule/asr.txt", DF|RF|NORF|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.464333 afpd[17568] {ad_open.c:992} (debug:ad): ad_open_df("/mnt/timecapsule/asr.txt", DF|RF|NORF|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.466415 afpd[17568] {ad_open.c:1058} (debug:ad): ad_open_df("/mnt/timecapsule/asr.txt", DF|RF|NORF|O_RDONLY): END: 0 [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.466784 afpd[17568] {ad_open.c:1386} (debug:ad): ad_open_rf("/mnt/timecapsule/asr.txt"): BEGIN
Apr 19 20:37:07.468449 afpd[17568] {ad_open.c:1512} (debug:ad): ad_open_rf("/mnt/timecapsule/asr.txt"): END: 0
Apr 19 20:37:07.469058 afpd[17568] {ad_open.c:1912} (debug:ad): ad_open("/mnt/timecapsule/asr.txt"): END: 0 {d: 1, m: 0, r: 0}[dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.469553 afpd[17568] {ad_lock.c:515} (debug:ad): ad_tmplock(data, WR, off: 0 (-), len: 0): BEGIN
Apr 19 20:37:07.470010 afpd[17568] {ad_lock.c:72} (debug:ad): set_lock(fd: 9, F_SETLK, F_RDLCK, off: 0 (-), len: 0): BEGIN
Apr 19 20:37:07.471064 afpd[17568] {ad_lock.c:567} (debug:ad): ad_tmplock: END: 0
Apr 19 20:37:07.476678 afpd[17568] {ad_flush.c:423} (debug:ad): ad_close(DF): BEGIN: {d: 1, m: 0, r: 0} [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Apr 19 20:37:07.478724 afpd[17568] {ad_flush.c:486} (debug:ad): ad_close(DF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Apr 19 20:37:07.479297 afpd[17568] {dircache.c:385} (debug:AFPDaemon): dircache_search_by_name(did:2, "asr.txt")
Apr 19 20:37:07.481241 afpd[17568] {dircache.c:408} (debug:AFPDaemon): dircache(did:2,"asr.txt"): {modified}
Apr 19 20:37:07.481761 afpd[17568] {directory.c:953} (debug:AFPDaemon): dir_remove(did:426,'asr.txt'): {removing}
Apr 19 20:37:07.482237 afpd[17568] {dircache.c:542} (debug:AFPDaemon): dircache(did:426,"asr.txt"): {removed}
Apr 19 20:37:07.482690 afpd[17568] {afp_dsi.c:633} (debug:AFPDaemon): ==> Finished AFP command: AFP_DELETE -> AFPERR_ACCESS
<<

I would really appreciate any help in tracking down the root cause of this.

Thank you,
Robert

[Daniel Markstedt]

Can you please clarify something: By "apple time capsule", do you mean an actual time capsule device's file system is mounted remotely and then shared by netatalk? Or is this a plain netatalk volume of the time machine type?

Looking at the log, the one hint that I see is that EA metadata for the file cannot be read, so the format of the metadata might be different than what netatalk expects, or it has been corrupted somehow.

[Daniel Markstedt]

The appledouble parsing and validation code has changed recently.