AFP and CNID DB Issue with 8.0.1 RC1 & FreeNAS-8.0.2-RELEASE

[victorhooi]

Hi,

I recently did a fresh install of FreeNas? 8.0.1 RC1 on my HP N36L micro-server.

I created a AFP share, and attempted to access it with a Macbook Pro, with OSX 10.7.1 installed.

On the Macbook, I get the error message:

Message from server "freenas"
Something wrong with the volume's CNID DB, using temporary CNID DB instead. Check server  messages for details. Switching to read-only mode

On the server, in /var/log/messages, I have:

Sep 11 10:28:54 freenas afpd[8635]: AFP3.3 Login by victorhooi
Sep 11 10:29:06 freenas cnid_dbd[8645]: Set syslog logging to level: LOG_NOTE
Sep 11 10:29:13 freenas cnid_dbd[8648]: Set syslog logging to level: LOG_NOTE
Sep 11 10:29:35 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:29:56 freenas last message repeated 22 times
Sep 11 10:29:56 freenas afpd[8635]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:29:56 freenas afpd[8635]: ===============================================================
Sep 11 10:29:56 freenas kernel: pid 8635 (afpd), uid 1001: exited on signal 6
Sep 11 10:29:56 freenas afpd[8635]: INTERNAL ERROR: Signal 10 in pid 8635 (2.2.0)
Sep 11 10:29:56 freenas afpd[8635]: ===============================================================
Sep 11 10:29:56 freenas afpd[8675]: AFP3.3 Login by victorhooi
Sep 11 10:29:56 freenas afpd[8675]: afp_disconnect: trying primary reconnect
Sep 11 10:29:56 freenas afpd[1767]: Reconnect: no child[8635]
Sep 11 10:30:01 freenas afpd[8675]: afp_disconnect: primary reconnect failed
Sep 11 10:30:01 freenas freenas[8683]: Popen()ing: zpool list -H -o health datastore
Sep 11 10:30:02 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:30:23 freenas last message repeated 22 times
Sep 11 10:30:23 freenas afpd[8675]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:30:23 freenas afpd[8675]: Reopen volume /mnt/datastore/photos using in memory temporary CNID DB.
Sep 11 10:34:00 freenas afpd[8675]: AFP logout by victorhooi
Sep 11 10:34:00 freenas afpd[8675]: AFP statistics: 3.04 KB read, 8.54 KB written
Sep 11 10:34:00 freenas afpd[8675]: done
Sep 11 10:34:07 freenas afpd[8717]: AFP3.3 Login by victorhooi
Sep 11 10:34:10 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:34:31 freenas last message repeated 22 times
Sep 11 10:34:31 freenas afpd[8717]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:34:31 freenas afpd[8717]: Reopen volume /mnt/datastore/photos using in memory temporary CNID DB.
Sep 11 10:34:31 freenas cnid_dbd[8722]: Set syslog logging to level: LOG_NOTE
Sep 11 10:34:33 freenas cnid_dbd[8728]: Set syslog logging to level: LOG_NOTE
Sep 11 10:34:34 freenas cnid_dbd[8735]: Set syslog logging to level: LOG_NOTE
Sep 11 10:35:01 freenas freenas[8765]: Popen()ing: zpool list -H -o health datastore
Sep 11 10:36:05 freenas afpd[8717]: AFP logout by victorhooi
Sep 11 10:36:05 freenas afpd[8717]: AFP statistics: 24.12 KB read, 108.73 KB written
Sep 11 10:36:05 freenas afpd[8717]: done
Sep 11 10:36:15 freenas afpd[8795]: AFP3.3 Login by victorhooi
Sep 11 10:36:19 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:36:40 freenas last message repeated 22 times
Sep 11 10:36:40 freenas afpd[8795]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:36:40 freenas afpd[8795]: enumerate(vid:11, did:2, name:'.'): error adding dir: 'photos - copied may 21, 2011'
Sep 11 10:36:40 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:37:01 freenas last message repeated 22 times
Sep 11 10:37:01 freenas afpd[8795]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:37:01 freenas afpd[8795]: ===============================================================
Sep 11 10:37:01 freenas kernel: pid 8795 (afpd), uid 1001: exited on signal 6
Sep 11 10:37:01 freenas afpd[8795]: INTERNAL ERROR: Signal 10 in pid 8795 (2.2.0)
Sep 11 10:37:01 freenas afpd[8795]: ===============================================================
Sep 11 10:37:01 freenas afpd[8812]: AFP3.3 Login by victorhooi
Sep 11 10:37:01 freenas afpd[8812]: afp_disconnect: trying primary reconnect
Sep 11 10:37:01 freenas afpd[1767]: Reconnect: no child[8795]
Sep 11 10:37:06 freenas afpd[8812]: afp_disconnect: primary reconnect failed
Sep 11 10:37:07 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:37:28 freenas last message repeated 22 times
Sep 11 10:37:28 freenas afpd[8812]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:37:28 freenas afpd[8812]: enumerate(vid:11, did:2, name:'.'): error adding dir: 'photos - copied may 21, 2011'
Sep 11 10:37:28 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:37:49 freenas last message repeated 22 times
Sep 11 10:37:49 freenas afpd[8812]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:37:49 freenas afpd[8812]: ===============================================================
Sep 11 10:37:49 freenas kernel: pid 8812 (afpd), uid 1001: exited on signal 6
Sep 11 10:37:49 freenas afpd[8812]: INTERNAL ERROR: Signal 10 in pid 8812 (2.2.0)
Sep 11 10:37:49 freenas afpd[8812]: ===============================================================
Sep 11 10:37:49 freenas afpd[8815]: AFP3.3 Login by victorhooi
Sep 11 10:37:49 freenas afpd[8815]: afp_disconnect: trying primary reconnect
Sep 11 10:37:49 freenas afpd[1767]: Reconnect: no child[8812]
Sep 11 10:37:54 freenas afpd[8815]: afp_disconnect: primary reconnect failed
Sep 11 10:37:55 freenas cnid_metad[1765]: allocvolinfo("/mnt/datastore/photos"): No such file or directory
Sep 11 10:38:16 freenas last message repeated 22 times
Sep 11 10:38:16 freenas afpd[8815]: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:38:16 freenas afpd[8815]: Reopen volume /mnt/datastore/photos using in memory temporary CNID DB.
Sep 11 10:40:01 freenas freenas[8829]: Popen()ing: zpool list -H -o health datastore

I didn't have this issue with the same Macbook and OSX version and FreeNas? 8.0. Does anybody know if there an issue with the new Netatalk and AFP in 8.0.1 RC1?

Cheers,
Victor

[gcooper]

Ran into this issue as well. If you fix the permissions, then things will go through just fine the next time you restart afpd. Not saying it isn't a valid issue, but that's how you workaround the issue.

Some of my files were owned by root, and I set the ownership to my UID, and voila.. things worked.

Either that or the Apple ACLs set when copying over the files via CIFS for testing screwed up the permissions (wouldn't be surprised).

Please confirm whether or not fixing the permissions either via the command line or the GUI (be sure to fix it recursively) fixes things.

[pierrep]

Freenas 8.0.1-RC2 with MacOS 10.6.8 (upgraded from FreeNAS 8.0 RELEASE)
same issue

question : how do you "fix" the permissions ??
on a multi users system, what is the right user ?

Besides i'd like to point out that my system was upgraded from 8.0 RELEASE so the pools, users and permissions are the same as before the upgrade but the AFP on 8.0.1-RC2 is not working...

HTH

[OneStickShortOfaBundle]

I've had this problem since RC1. I'm currently using 8.0.1-RELEASE-amd64 and it persists. How do I fix the permission?

Update - I have just set up a completely new NAS and installed FreeNAS-8.0.1-RELEASE-amd64 on it and exactly the same problem has reoccurred with the new AFP I made. How do I fix this?

[pierrep]

i'll add my logs here (i wrongfully created ticket 876...)
NB : This is 8.0.1-RELEASE logs since i upgraded my 8.0.1.RC2 to 8.0.1-RELEASE since last time

On the server i get the following log at startup of AFP :

Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service ix-afpd quietstart
Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service netatalk forcestop
Oct  3 23:03:18 freenas freenas: No matching processes were found
Oct  3 23:03:18 freenas freenas: No matching processes were found
Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service dbus forcestop
Oct  3 23:03:18 freenas freenas: Stopping dbus.
Oct  3 23:03:18 freenas avahi-daemon[44614]: Disconnected from D-Bus, exiting.
Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service dbus restart
Oct  3 23:03:18 freenas freenas: dbus not running? (check /var/run/dbus/dbus.pid).
Oct  3 23:03:18 freenas freenas: Starting dbus.
Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service avahi-daemon forcestop
Oct  3 23:03:18 freenas freenas: Stopping avahi-daemon.
Oct  3 23:03:18 freenas freenas: Failed to kill daemon: No such file or directory
Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service avahi-daemon restart
Oct  3 23:03:18 freenas freenas: Stopping avahi-daemon.
Oct  3 23:03:18 freenas freenas: Failed to kill daemon: No such file or directory
Oct  3 23:03:18 freenas freenas: Starting avahi-daemon.
Oct  3 23:03:18 freenas avahi-daemon[44923]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Oct  3 23:03:18 freenas freenas[1725]: Executing: /usr/sbin/service netatalk restart
Oct  3 23:03:19 freenas freenas: No matching processes were found
Oct  3 23:03:19 freenas freenas: No matching processes were found
Oct  3 23:03:19 freenas cnid_metad[44938]: Set syslog logging to level: LOG_NOTE
Oct  3 23:03:19 freenas [44940]: Set syslog logging to level: LOG_NOTE
Oct  3 23:03:19 freenas afpd[44941]: AFP/TCP started, advertising xxx.xxx.xxx.xxx:548 (2.2.0)
Oct  3 23:03:21 freenas freenas[1725]: Executing: /bin/pgrep -F /var/run/afpd.pid afpd
Oct  3 23:03:23 freenas afpd[44941]: bind(fd, (struct sockaddr *)&address, address_length) failed: Address already in use

then when accessing one of my shares and logging in :

Oct  3 23:05:00 freenas afpd[45035]: AFP3.3 Login by nobody
Oct  3 23:05:04 freenas afpd[45035]: AFP logout by nobody
Oct  3 23:05:04 freenas afpd[45035]: dsi_stream_read: len:0, unexpected EOF
Oct  3 23:05:04 freenas afpd[45035]: afp_over_dsi: client logged out, terminating DSI session
Oct  3 23:05:04 freenas afpd[45035]: AFP statistics: 0.37 KB read, 0.36 KB written
Oct  3 23:05:13 freenas afpd[45079]: AFP3.3 Login by pierre
Oct  3 23:05:22 freenas cnid_metad[44939]: allocvolinfo("/mnt/pool/sharename"): No such file or directory
Oct  3 23:05:43 freenas last message repeated 22 times
Oct  3 23:05:43 freenas afpd[45079]: transmit: Request to dbd daemon (db_dir /mnt/pool/sharename) timed out.
Oct  3 23:05:43 freenas afpd[45079]: Reopen volume /mnt/pool/sharename using in memory temporary CNID DB.

[OneStickShortOfaBundle]

In addition to the CNID DB problem 43,033 invisible ‘.AppleDouble?’ folders and 12,790 visible ‘I7CIPB~N’ files have appeared on my server. Is it safe for me to delete all these files?

[gcooper]

Figured out what the problem was.

The error is stating "permission denied" in a non-intuitive way. OSX likes dropping .AppleDB files everywhere, and unfortunately it's just not clear based on the error message what's happening until you go digging through some other webpages and figure out what the issue is.

I'll file a bug upstream to improve the error message or create a FAQ at least that's going to be crawled by Google so we can point other folks to it; all that really needs to be done to remedy the issue is that you need to adjust your permissions so your guest or login account can write the .AppleDB files to the share. Once you do that, the problems both you and I have seen above will go away.

[OneStickShortOfaBundle]

Please can someone tell me how to resolve this CNID DB problem before I am forced to abandon FreeNAS altogether and look for alternate NAS software. I have tried all the advice that has been given but I am still locked out of my server several weeks after the problem began.

I do not know how to allow access to the .AppleDB files with my Mac. There does not seem to be any way to do this from the GUI and I do not possess the knowledge to do it from the Terminal.

This ticket has not been resolved for those of us using the GUI. Far more detailed guidance is needed to enact a fix.

[OneStickShortOfaBundle]

I’m afraid that none of the advice has worked. I still can’t write to my server. The only thing that I can think of is to delete the whole ZFS RAID volume and create a new one then restore the data from the backup. Are there any last suggestions before I take this drastic step?

[gcooper]

Change the guest account mapping because as it says in the logs, it's trying to access the share as nobody:nobody, the most restricted account, and it probably can't access your share files.

Again, the error message is lousy and doesn't tell me in an intuitive manner _why_ I can't write out the CNID DB files (the doubleapple files)..

[gcooper]

(Reposting because Trac isn't emailing the additional edits to the ticket in my previous post)

Change the guest account mapping because as it says in the logs, it's trying to access the share as nobody:nobody, the most restricted account, and it probably can't access your share files.

Again, the error message is lousy and doesn't tell me in an intuitive manner _why_ I can't write out the CNID DB files (the doubleapple files)..

[pierrep]

Definitely not working in 8.0.2
I did some tests to try and figure out what access rights are needed, but nothing worked !
Even creating the .AppleDB folder and setting it to 777 did not help....

1 question i have : why do all forked processes use the same file to store their PID ? That does not seem right to me...

anyways, here are the files, in case it is of use somehow

[pierrep]

pierrep comment 12

[pierrep]

pierrep comment 12

[pierrep]

pierrep comment 12

[pierrep]

pierrep comment 12

[pierrep]

pierrep comment 12

[gcooper]

I've tried again with a 8.0.3-BETA2/i386 (not available for public consumption yet, but 8.0.3-BETA1 should suffice for your purposes) test image backing up my Macbook with 10.6.8 (Snow Leopard), and it works reasonably well considering my test hardware: 30GB / 87GB transferred over wireless from my 4 year old Macbook with 802.11g, using cheap, dumb Netgear switches served up via a Realtek NIC on a Windows 7 machine hosting a VirtualBox? VM (I know it can go faster -- I've seen it before with better hardware and a better config).

There are caveats to setting up afp in order to get stuff to work; you don't have to set things up exactly as shown, but please use it as a reference for setting things up properly. I'm attaching screenshots with settings that worked for me.

Again, _you must set the permissions for the volume/dataset appropriately or things will fail as shown above_. And just to reiterate, _do not set recursive permissions in the GUI_; do the following and your setup will be as you expect:

1. Go into the GUI and configure the permissions for just the volume/dataset, s.t. you can change the permissions appropriately on another client (Unix, OSX, Windows, whatever). Set your ACL setting appropriately; 'Windows' for Windows interoperability, or 'Unix' for POSIX ACL interoperability; I recommend the 'Windows' setting because it's NFSv4 ACLs which are going to obsolete the 'Unix' (aka POSIX) setting sometime in the next couple years.
2. Use your client to set the permissions appropriately. Finder, Explorer, a Terminal / Putty session, etc will suffice.
3. Do not change the permissions in the GUI ever again -- except as a last resort.

Last but not least: setting up / connecting to the netatalk server via Finder and not via Command-K is a bad idea. A really bad idea in fact because connecting via the Finder defaults to using UDP and netatalk is horrible when it comes to receiving UDP datagrams we discovered with an older version of netatalk.

Finally, my VM has been provisioned very little RAM (2GB), but I'm seeing SIGABRT+SIGBUS errors in your /var/log/messages; SIGBUS from what I've seen is either uninitialized memory or a sign that ZFS has eaten up all your RAM and then userland apps try to grab more to play with they fail, then reference memory addresses outside what's addressable... I don't know what the issue is with your configuration, but with my configuration as shown, everything works on my end, despite the fact that the configuration is suboptimal.

I'll wash-rinse-repeat the procedure with my Lion based Macbook Pro to ensure that everything functions with 10.7.2, but I'd say this is pretty much case closed again as Worksforme for you pierrep given the info you provided in the 8.0.3 forums announcement.

Something to keep in mind:

1. It might have been fixed with the netatalk 2.2.1 upgrade (which is available in 8.0.3+).
2. Something else I imported to fix AFP for customers might have fixed things for you as well.

If you need help and things still don't work, I'll be more than happy to assist on the forums (please PM me to point me to a thread you started).

[gcooper]

As a followup, the TimeMachine? dump from my old Macbook completed just fine, and my new Macbook with Lion had the same success.

[cjoy]

I can not confirm the proposed fix to solve this issue.

Restating the issue:
When connecting to the problematic AFP share volume from OS X the connection will timeout or an error is thrown ("Something wrong with the volume's CNID DB, using temporary CNID DB instead. Check server messages for details. Switching to read-only mode")

/var/log/messages with comments:

// connecting to the afp share with uname/passwd, all volumes get listed
afpd[5152]: AFP3.3 Login by username 
// traversing finder into afp volume FOO - everything works, no messages output
// traversing finder into afp volume BAR - timeout or error message as in #1 , reflected in log by:
kernel: pid 5226 (cnid_dbd), uid 1002: exited on signal 11
kernel: pid 5227 (cnid_dbd), uid 1002: exited on signal 11
kernel: pid 5228 (cnid_dbd), uid 1002: exited on signal 11
// ... repeat 15 ...
kernel: pid 5240 (cnid_dbd), uid 1002: exited on signal 11
afpd[5152]: transmit: Request to dbd daemon (db_dir /mnt/BAR) timed out.
kernel: pid 5241 (cnid_dbd), uid 1002: exited on signal 11
afpd[5152]: enumerate(vid:4, did:2, name:'.'): error adding dir: 'SomeFolder'
cnid_metad[2271]: error in sendmsg: Broken pipe

As suggested I looked at permissions and rebuild them using
"chown -R username:username /mnt/BAR"
and also via the FreeNAS GUI

In both cases the AFP service was toggled off/on and the server rebooted.
The problem however, persists.

Environment:

OS X 10.7.X, 10.8.X

FreeNAS-8.3.0-RELEASE-p1-x64 (r12825)
Platform	AMD Turion(tm) II Neo N40L Dual-Core Processor

ZFS Volume
drwxrwxr--    username:username 
Type of ACL: Unix

AFP Share Settings
Share Passwd: (unset)
Allow List: username
Disk Discovery enabled
Disk discovery mode: Default
Database Path: (unset)
Cache CNID: 0	 
Translate CR/LF: 0	 
Windows File Names: 0	 
Enable .AppleDouble	: 1 
Zero Device Numbers: 0	 
Disable File ID: 0	 
Disable :hex Names: 0	 
ProDOS: 0	 
No Stat: 0	 
AFP3 Unix Privs: 1	 


cnid_dbd (Netatalk 2.2.3)
cnid_metad (Netatalk 2.2.3)
afpd 2.2.3 - Apple Filing Protocol (AFP) daemon of Netatalk
afpd has been compiled with support for these features:
AFP versions:	2.2 3.0 3.1 3.2 3.3
DDP(AppleTalk) Support:	No
CNID backends:	dbd last tdb
afpd.conf:	/usr/local/etc/afpd.conf
AppleVolumes.system:	/usr/local/etc/AppleVolumes.system
AppleVolumes.default:	/usr/local/etc/AppleVolumes.default
afp_signature.conf:	/usr/local/etc/afp_signature.conf
afp_voluuid.conf:	/usr/local/etc/afp_voluuid.conf
afp_ldap.conf:	not supported
UAM search path:	/usr/local/libexec/netatalk-uams/
Server messages path:	/usr/local/etc/msg/
lockfile:	/var/spool/lock/afpd

[jpaetzel]

# dbd -r /path/to/share should work. It will rebuild the appledouble files. This may take a while if the share is large.

This is run on the FreeNAS box as root from the shell.

[dwhite]

Do you have a reproduction case for this crash from a fresh install and a new volume?

[cjoy]

Replying to jpaetzel:

# dbd -r /path/to/share should work. It will rebuild the appledouble files. This may take a while if the share is large.

This is run on the FreeNAS box as root from the shell.

.

dbd did the trick.

although "dbd -r" alone did not suffice: the process was always terminated with a "Segmentation fault" error. "dbd -rv" (verbose) showed that the error occured when trying to write to the db.
Dumping the db via "dbd -d" also resulted in an error, so apparently the CNID db itself was damaged or otherwise inaccessible for write tasks.

-> Wiping and fully rebuilding the db via "dbd -rf" finally resolved the problem. <-

All OS X clients can now read/write to the share again.

---

While this worked for me, please make sure to read the dbd man page and adhere to the warnings before wiping your CNID db.

---

Many thanks to jpaetzel for the prompt assistance and pointing out dbd!

[dwhite]

Closing this ticket as Invalid as issue was determined to be not due to a bug. If you can reproduce the CNID DB data corruption please open a new ticket with the instructions to reproduce said corruption.