Netatalk issues with CNID

Khaine · Jan 14, 2013

I've just set up a HP Microserver as a NAS. I choose FreeBSD 9.1 with a ZFS root, in a raidz1 configuration. I set up, netatalk 3.0.1 and avahi. I can see my shares on the network, and I can connect to the server. Initially I could copy data onto it, but now whenever I try I get the following error:

Code:

"something wrong with the volume's cnid DB, using temporary cnid db instead. Check server messages for details. Switching to read only mode"

When I look at the server log I get the following:

Code:

 {cnid_dbd.c:420} (E:CNID): transmit: Request to dbd daemon (db_dir /media/photos) timed out.
Jan 13 12:46:29.905855 afpd[39248] {file.c:239} (E:AFPDaemon): Reopen volume /media/photos using in memory temporary CNID DB.

the permission on the volume are:

Code:

drwxr-xr-x 7 root wheel 7B Jan 12 21:16 .
drwxr-xr-x 18 root wheel 23B Jan 12 20:07 ..
drwxrwx--- 2 khainebot wheel 3B Jan 13 12:46 photos

My afp.conf is as follows:

Code:

 Netatalk 3.x configuration file
;

[Global]
; Global server settings

log level = default:info
log file = /var/log/netatalk.log
mimic model = XServe
cnid scheme = dbd

uam lust = uams_dhx.so,uams_dhx2.so
save password = no

[TV Shows]
path = /media/tv shows
cnid scheme = dbd

[Movies]
path = /media/movies
cnid scheme = dbd

[Music]
path = /media/music
cnid scheme = dbd

[Backup]
path = /media/backup
time machine = yes
cnid scheme = dbd

[Photos]
path = /media/photos
cnid scheme = dbd

I have tried changing the CNID backend, to no avail. I have no idea how to progress fixing this. Any help would be greatly appreciated.

Khaine · Jan 16, 2013

I ran netatalk with the log outout to debug. I got the following:

Code:

Jan 16 21:35:23.215160 afpd[78618] {file.c:292} (D5:AFPDaemon): getmetadata(".DS_Store")
Jan 16 21:35:23.215193 afpd[78618] {ad_lock.c:604} (D5:Default): ad_testlock(data, off: 9223372036854775799 (OPEN_RD_DATA): BEGIN
Jan 16 21:35:23.215220 afpd[78618] {ad_lock.c:72} (D5:Default): set_lock(fd: 5, F_GETLK, F_WRLCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 16 21:35:23.215254 afpd[78618] {ad_lock.c:614} (D5:Default): ad_testlock: END: 0
Jan 16 21:35:23.215280 afpd[78618] {ad_lock.c:604} (D5:Default): ad_testlock(data, off: 9223372036854775803 (DENY_RD_DATA): BEGIN
Jan 16 21:35:23.215306 afpd[78618] {ad_lock.c:72} (D5:Default): set_lock(fd: 5, F_GETLK, F_WRLCK, off: 9223372036854775803 (DENY_RD_DATA), len: 1): BEGIN
Jan 16 21:35:23.215334 afpd[78618] {ad_lock.c:614} (D5:Default): ad_testlock: END: 0
Jan 16 21:35:23.215365 afpd[78618] {ad_lock.c:369} (D5:Default): ad_lock(data, RD|FILELOCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 16 21:35:23.215391 afpd[78618] {ad_lock.c:72} (D5:Default): set_lock(fd: 5, F_SETLK, F_RDLCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 16 21:35:23.215424 afpd[78618] {ad_lock.c:499} (D5:Default): ad_lock: END: 0
Jan 16 21:35:23.215451 afpd[78618] {fork.c:480} (D5:AFPDaemon): afp_openfork("/media/photos/.DS_Store"): fork: 1
Jan 16 21:35:23.215476 afpd[78618] {afp_dsi.c:633} (D5:AFPDaemon): ==> Finished AFP command: AFP_OPENFORK -> AFP_OK
Jan 16 21:35:23.215500 afpd[78618] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 71, len: 4): START
Jan 16 21:35:23.215556 afpd[78618] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 71, len: 4): END
Jan 16 21:35:23.215588 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.215613 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.218670 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.218764 afpd[78618] {dsi_stream.c:603} (D5:DSI): dsi_stream_receive: DSI cmdlen: 20
Jan 16 21:35:23.218793 afpd[78618] {afp_dsi.c:611} (D5:DSI): DSI request ID: 72
Jan 16 21:35:23.218819 afpd[78618] {afp_dsi.c:626} (D5:AFPDaemon): <== Start AFP command: AFP_READ_EXT
Jan 16 21:35:23.218878 afpd[78618] {fork.c:801} (D5:AFPDaemon): afp_read(fork: 1 [data], off: 0, len: 6148, size: 6148)
Jan 16 21:35:23.218954 afpd[78618] {fork.c:850} (D5:AFPDaemon): afp_read(name: ".DS_Store", offset: 0, reqcount: 6148): got 6148 bytes from file
Jan 16 21:35:23.219017 afpd[78618] {afp_dsi.c:633} (D5:AFPDaemon): ==> Finished AFP command: AFP_READ_EXT -> AFP_OK
Jan 16 21:35:23.219058 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.219086 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.238081 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.238175 afpd[78618] {dsi_stream.c:603} (D5:DSI): dsi_stream_receive: DSI cmdlen: 4
Jan 16 21:35:23.238201 afpd[78618] {afp_dsi.c:611} (D5:DSI): DSI request ID: 73
Jan 16 21:35:23.238226 afpd[78618] {afp_dsi.c:626} (D5:AFPDaemon): <== Start AFP command: AFP_CLOSEFORK
Jan 16 21:35:23.238252 afpd[78618] {fork.c:1039} (D5:AFPDaemon): afp_closefork(fork: 1 [data])
Jan 16 21:35:23.238283 afpd[78618] {ad_lock.c:574} (D5:Default): ad_unlock(unlckbrl: 1): BEGIN
Jan 16 21:35:23.238312 afpd[78618] {ad_lock.c:72} (D5:Default): set_lock(fd: 5, F_SETLK, F_UNLCK, off: 9223372036854775799 (OPEN_RD_DATA), len: 1): BEGIN
Jan 16 21:35:23.238357 afpd[78618] {ad_lock.c:583} (D5:Default): ad_unlock: END
Jan 16 21:35:23.238387 afpd[78618] {ad_flush.c:403} (D5:Default): ad_close(DF|HF|SHRMD): BEGIN: {d: 1, m: 1, r: 0} [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jan 16 21:35:23.238436 afpd[78618] {ad_flush.c:457} (D5:Default): ad_close(DF|HF|SHRMD): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 16 21:35:23.238464 afpd[78618] {afp_dsi.c:633} (D5:AFPDaemon): ==> Finished AFP command: AFP_CLOSEFORK -> AFP_OK
Jan 16 21:35:23.238491 afpd[78618] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 73, len: 0): START
Jan 16 21:35:23.238539 afpd[78618] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 73, len: 0): END
Jan 16 21:35:23.238572 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.238598 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.240306 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.240395 afpd[78618] {dsi_stream.c:603} (D5:DSI): dsi_stream_receive: DSI cmdlen: 28
Jan 16 21:35:23.240423 afpd[78618] {afp_dsi.c:611} (D5:DSI): DSI request ID: 74
Jan 16 21:35:23.240449 afpd[78618] {afp_dsi.c:626} (D5:AFPDaemon): <== Start AFP command: AFP_GETFLDRPARAM
Jan 16 21:35:23.240474 afpd[78618] {directory.c:557} (D5:AFPDaemon): dirlookup(did: 2): START
Jan 16 21:35:23.240500 afpd[78618] {directory.c:703} (D5:AFPDaemon): dirlookup(did: 2): RESULT: pdid: 1, path: "/media/photos"
Jan 16 21:35:23.240525 afpd[78618] {directory.c:1300} (D5:AFPDaemon): movecwd(to: did: 2, "/media/photos")
Jan 16 21:35:23.240596 afpd[78618] {directory.c:1206} (D5:AFPDaemon): came('/media/photos'): {file: '.DS_Store'}
Jan 16 21:35:23.240621 afpd[78618] {directory.c:1271} (D5:AFPDaemon): came('/media/photos') {end: curdir:'/media/photos', path:'.DS_Store'}
Jan 16 21:35:23.240645 afpd[78618] {filedir.c:82} (D5:AFPDaemon): getfildirparams(vid:10, did:2, f/d:e93f/a33f) {cwdid:2, cwd: /media/photos, name:'.DS_Store'}
Jan 16 21:35:23.240668 afpd[78618] {file.c:599} (D5:AFPDaemon): getfilparams(".DS_Store")
Jan 16 21:35:23.240700 afpd[78618] {ad_open.c:1613} (D5:Default): ad_open("/media/photos/.DS_Store", HF|OF|O_RDONLY): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 16 21:35:23.240730 afpd[78618] {ad_open.c:820} (D5:Default): ad_open_df("/media/photos/.DS_Store", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 16 21:35:23.240770 afpd[78618] {ad_open.c:886} (D5:Default): ad_open_df("/media/photos/.DS_Store", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jan 16 21:35:23.240801 afpd[78618] {ad_open.c:1034} (D5:Default): ad_open_hf_ea("/media/photos/.DS_Store", DF|HF|OF|SHRMD|O_RDONLY): BEGIN [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jan 16 21:35:23.240878 afpd[78618] {ad_open.c:1147} (D5:Default): ad_reso_size(".DS_Store"): BEGIN
Jan 16 21:35:23.240914 afpd[78618] {ad_open.c:1104} (D5:Default): ad_open_hf_ea("/media/photos/.DS_Store", DF|HF|OF|SHRMD|O_RDONLY): END: 0 [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jan 16 21:35:23.240942 afpd[78618] {ad_lock.c:72} (D5:Default): set_lock(fd: 5, F_GETLK, F_WRLCK, off: 9223372036854775798 (OPEN_WR_DATA), len: 4): BEGIN
Jan 16 21:35:23.240977 afpd[78618] {ad_open.c:1680} (D5:Default): ad_open("/media/photos/.DS_Store"): END: 0 {d: 1, m: 1, r: 0}[dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jan 16 21:35:23.241002 afpd[78618] {file.c:292} (D5:AFPDaemon): getmetadata(".DS_Store")
Jan 16 21:35:23.241026 afpd[78618] {dircache.c:385} (D5:AFPDaemon): dircache_search_by_name(did:2, ".DS_Store")
Jan 16 21:35:23.241070 afpd[78618] {dircache.c:414} (D5:AFPDaemon): dircache(did:2,".DS_Store"): {found in cache}
Jan 16 21:35:23.241096 afpd[78618] {file.c:380} (D5:AFPDaemon): metadata('.DS_Store'): AFP Attributes: 0001
Jan 16 21:35:23.241120 afpd[78618] {file.c:387} (D5:AFPDaemon): metadata('.DS_Store'):     Parent DID: 2
Jan 16 21:35:23.241145 afpd[78618] {file.c:435} (D5:AFPDaemon): metadata('.DS_Store'):           CNID: 17
Jan 16 21:35:23.241173 afpd[78618] {ad_flush.c:403} (D5:Default): ad_close(HF|OF): BEGIN: {d: 1, m: 1, r: 0} [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jan 16 21:35:23.241205 afpd[78618] {ad_flush.c:457} (D5:Default): ad_close(DF|HF|OF): END: 0 {d: 0, m: 0, r: 0} [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jan 16 21:35:23.241228 afpd[78618] {afp_dsi.c:633} (D5:AFPDaemon): ==> Finished AFP command: AFP_GETFLDRPARAM -> AFP_OK
Jan 16 21:35:23.241251 afpd[78618] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 74, len: 113): START
Jan 16 21:35:23.241296 afpd[78618] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 74, len: 113): END
Jan 16 21:35:23.241325 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.241349 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Jan 16 21:35:23.273518 afpd[78618] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0

From this I still have no idea why there are issues with the cnid database

kpa · Jan 16, 2013

There was a very recent update to the port to address a CNID database problem:

http://www.freshports.org/net/netatalk3/

Update to version 3.0.1_1,1 and see if it fixes your problem.

Khaine · Jan 17, 2013

Thanks. I updated to version 3.0.1_1,1 and still have the same issue. Here is the log from the updated version of netatalk

Code:

Jan 17 17:54:50.996225 netatalk[16905] {netatalk.c:280} (N:Default): Netatalk AFP server starting
Jan 17 17:54:51.001269 cnid_metad[16907] {usockfd.c:120} (I:CNID): tsockfd_create: bind: Address already in use

Jan 17 17:54:51.001728 cnid_metad[16907] {cnid_metad.c:519} (N:AFPDaemon): CNID Server listening on localhost:4700
Jan 17 17:54:52.530932 afpd[16906] {status.c:791} (I:AFPDaemon): signature is C57EE82EFE7815CB2D91D615FCB7BC04
Jan 17 17:55:03.564046 afpd[16906] {dsi_tcp.c:400} (I:DSI): dsi_tcp_init: getaddrinfo 'freebsd-server': hostname nor servname provided, or not known

Jan 17 17:55:03.564250 afpd[16906] {dsi_tcp.c:269} (I:DSI): dsi_tcp: '10.0.0.60:548' on interface 'bge0' will be used instead.
Jan 17 17:55:03.564427 afpd[16906] {auth.c:108} (I:AFPDaemon): uam: "DHX2" available
Jan 17 17:55:03.564467 afpd[16906] {auth.c:108} (I:AFPDaemon): uam: "DHCAST128" available
Jan 17 17:55:03.564504 afpd[16906] {status.c:510} (I:AFPDaemon): servername: freebsd-server
Jan 17 17:55:03.564547 afpd[16906] {afp_config.c:109} (N:AFPDaemon): Netatalk AFP/TCP listening on 10.0.0.60:548
Jan 17 17:55:03.571838 afpd[16906] {afp_avahi.c:81} (I:AFPDaemon): Registering volume 'Backup' with UUID: 'A246477B-0842-7F5A-C637-893BF793EF7A' for TimeMachine
Jan 17 17:55:03.571944 afpd[16906] {afp_avahi.c:97} (I:AFPDaemon): hostname: consus
Jan 17 17:55:03.571983 afpd[16906] {afp_avahi.c:114} (I:AFPDaemon): Registering server 'freebsd-server' with Bonjour
Jan 17 17:55:03.574056 afpd[16906] {afp_avahi.c:312} (I:AFPDaemon): Successfully started avahi loop.
Jan 17 17:55:03.574277 afpd[16906] {cnid.c:54} (I:AFPDaemon): Registering CNID module [last]
Jan 17 17:55:03.574317 afpd[16906] {cnid.c:54} (I:AFPDaemon): Registering CNID module [dbd]
Jan 17 17:55:03.574354 afpd[16906] {cnid.c:54} (I:AFPDaemon): Registering CNID module [tdb]
Jan 17 17:55:03.576827 afpd[16923] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52227
Jan 17 17:55:03.577179 afpd[16906] {main.c:179} (I:AFPDaemon): child[16922]: exited 1
Jan 17 17:55:03.578189 afpd[16906] {main.c:179} (I:AFPDaemon): child[16924]: exited 1
Jan 17 17:55:03.578504 afpd[16925] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52229
Jan 17 17:55:03.580186 afpd[16927] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52231
Jan 17 17:55:03.580802 afpd[16906] {main.c:179} (I:AFPDaemon): child[16926]: exited 1
Jan 17 17:55:03.581838 afpd[16906] {main.c:179} (I:AFPDaemon): child[16928]: exited 1
Jan 17 17:55:03.581923 afpd[16929] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52233
Jan 17 17:55:03.640545 afpd[16906] {main.c:181} (I:AFPDaemon): child[16925]: done
Jan 17 17:55:03.640958 afpd[16906] {main.c:181} (I:AFPDaemon): child[16923]: done
Jan 17 17:55:03.641338 afpd[16906] {main.c:181} (I:AFPDaemon): child[16929]: done
Jan 17 17:55:03.641915 afpd[16906] {main.c:181} (I:AFPDaemon): child[16927]: done
Jan 17 17:55:09.990687 afpd[16930] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52234
Jan 17 17:55:09.993420 afpd[16930] {uams_dhx2_pam.c:325} (I:UAMS): DHX2 login: family
Jan 17 17:55:10.035131 afpd[16930] {uams_dhx2_pam.c:210} (I:UAMS): PAM DHX2: PAM Success
Jan 17 17:55:10.043728 afpd[16930] {uams_dhx2_pam.c:210} (I:UAMS): PAM DHX2: PAM Success
Jan 17 17:55:10.044200 afpd[16930] {uams_dhx2_pam.c:705} (I:UAMS): DHX2: PAM Auth OK!
Jan 17 17:55:10.044244 afpd[16930] {auth.c:242} (N:AFPDaemon): AFP3.3 Login by khaine
Jan 17 17:55:37.565683 afpd[16930] {cnid_dbd.c:420} (E:CNID): transmit: Request to dbd daemon (db_dir /media/photos) timed out.
Jan 17 17:55:37.565836 afpd[16930] {file.c:239} (E:AFPDaemon): Reopen volume /media/photos using in memory temporary CNID DB.
Jan 17 17:55:37.608871 afpd[16906] {main.c:179} (I:AFPDaemon): child[16931]: exited 1
Jan 17 17:55:37.610926 afpd[16932] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52238
Jan 17 17:55:37.614009 afpd[16906] {main.c:181} (I:AFPDaemon): child[16932]: done
Jan 17 17:55:37.645625 afpd[16906] {main.c:179} (I:AFPDaemon): child[16933]: exited 1
Jan 17 17:55:37.647118 afpd[16934] {dsi_tcp.c:221} (I:DSI): AFP/TCP session from 10.0.0.59:52240
Jan 17 17:55:37.650559 afpd[16906] {main.c:181} (I:AFPDaemon): child[16934]: done

Khaine · Jan 18, 2013

Well I restarted my server and it seems to resolve itself. I have no idea why that resolved it, but it did.

Khaine · Jan 18, 2013

I spoke to soon. I can copy files onto the shared location but I can't create folders. I see the following in the netatalk log

Code:

Jan 18 23:59:27.248219 afpd[1311] {directory.c:2021} (I:AFPDaemon): setdirparams("/media/photos/Europe/."): setdirunixmode: Operation not permitted
Jan 18 23:59:28.291613 afpd[1311] {directory.c:2021} (I:AFPDaemon): setdirparams("/media/photos/SouthAmerica/."): setdirunixmode: Operation not permitted

kpa · Jan 18, 2013

I can't offer more help unfortunately, I went back to the old port net/netatalk when I couldn't get the newer version working properly.

Khaine · Jan 22, 2013

Thanks for your help. I raised it as bug so hopefully it will get fixed.

Matty · Mar 1, 2013

I have this config. Give it a try and see if it works for you

Code:

[Global]
; Global server settings
vol preset = default_for_all_vol
log file = /var/log/netatalk.log
uam list = uams_dhx.so,uams_dhx2.so
save password = yes
afp listen = 192.168.2.3

[default_for_all_vol]
file perm = 0664
directory perm = 0774
ea = auto
cnid scheme = dbd

Khaine · Mar 2, 2013

Thanks for the suggestion. I managed to fix it by making the user a part of the group who owns the directories. Apparently it is a bug in netatalk which is fixed by this patch http://sourceforge.net/p/netatalk/code/ci/5e0444c335b5afc0f86fab91ed1f02de9bdf2835/