Project

General

Profile

Bug #763

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

Added by Victor Hooi about 8 years ago. Updated over 6 years ago.

Status:
Closed
Priority:
Important
Assignee:
-
Category:
Middleware
Target version:
-
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

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 afpdr8635: AFP3.3 Login by victorhooi
Sep 11 10:29:06 freenas cnid_dbdr8645: Set syslog logging to level: LOG_NOTE
Sep 11 10:29:13 freenas cnid_dbdr8648: Set syslog logging to level: LOG_NOTE
Sep 11 10:29:35 freenas cnid_metadr1765: 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 afpdr8635: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:29:56 freenas afpdr8635: ===============================================================
Sep 11 10:29:56 freenas kernel: pid 8635 (afpd), uid 1001: exited on signal 6
Sep 11 10:29:56 freenas afpdr8635: INTERNAL ERROR: Signal 10 in pid 8635 (2.2.0)
Sep 11 10:29:56 freenas afpdr8635: ===============================================================
Sep 11 10:29:56 freenas afpdr8675: AFP3.3 Login by victorhooi
Sep 11 10:29:56 freenas afpdr8675: afp_disconnect: trying primary reconnect
Sep 11 10:29:56 freenas afpdr1767: Reconnect: no childr8635
Sep 11 10:30:01 freenas afpdr8675: afp_disconnect: primary reconnect failed
Sep 11 10:30:01 freenas freenasr8683: Popen()ing: zpool list -H -o health datastore
Sep 11 10:30:02 freenas cnid_metadr1765: 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 afpdr8675: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:30:23 freenas afpdr8675: Reopen volume /mnt/datastore/photos using in memory temporary CNID DB.
Sep 11 10:34:00 freenas afpdr8675: AFP logout by victorhooi
Sep 11 10:34:00 freenas afpdr8675: AFP statistics: 3.04 KB read, 8.54 KB written
Sep 11 10:34:00 freenas afpdr8675: done
Sep 11 10:34:07 freenas afpdr8717: AFP3.3 Login by victorhooi
Sep 11 10:34:10 freenas cnid_metadr1765: 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 afpdr8717: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:34:31 freenas afpdr8717: Reopen volume /mnt/datastore/photos using in memory temporary CNID DB.
Sep 11 10:34:31 freenas cnid_dbdr8722: Set syslog logging to level: LOG_NOTE
Sep 11 10:34:33 freenas cnid_dbdr8728: Set syslog logging to level: LOG_NOTE
Sep 11 10:34:34 freenas cnid_dbdr8735: Set syslog logging to level: LOG_NOTE
Sep 11 10:35:01 freenas freenasr8765: Popen()ing: zpool list -H -o health datastore
Sep 11 10:36:05 freenas afpdr8717: AFP logout by victorhooi
Sep 11 10:36:05 freenas afpdr8717: AFP statistics: 24.12 KB read, 108.73 KB written
Sep 11 10:36:05 freenas afpdr8717: done
Sep 11 10:36:15 freenas afpdr8795: AFP3.3 Login by victorhooi
Sep 11 10:36:19 freenas cnid_metadr1765: 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 afpdr8795: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:36:40 freenas afpdr8795: enumerate(vid:11, did:2, name:'.'): error adding dir: 'photos - copied may 21, 2011'
Sep 11 10:36:40 freenas cnid_metadr1765: 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 afpdr8795: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:37:01 freenas afpdr8795: ===============================================================
Sep 11 10:37:01 freenas kernel: pid 8795 (afpd), uid 1001: exited on signal 6
Sep 11 10:37:01 freenas afpdr8795: INTERNAL ERROR: Signal 10 in pid 8795 (2.2.0)
Sep 11 10:37:01 freenas afpdr8795: ===============================================================
Sep 11 10:37:01 freenas afpdr8812: AFP3.3 Login by victorhooi
Sep 11 10:37:01 freenas afpdr8812: afp_disconnect: trying primary reconnect
Sep 11 10:37:01 freenas afpdr1767: Reconnect: no childr8795
Sep 11 10:37:06 freenas afpdr8812: afp_disconnect: primary reconnect failed
Sep 11 10:37:07 freenas cnid_metadr1765: 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 afpdr8812: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:37:28 freenas afpdr8812: enumerate(vid:11, did:2, name:'.'): error adding dir: 'photos - copied may 21, 2011'
Sep 11 10:37:28 freenas cnid_metadr1765: 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 afpdr8812: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:37:49 freenas afpdr8812: ===============================================================
Sep 11 10:37:49 freenas kernel: pid 8812 (afpd), uid 1001: exited on signal 6
Sep 11 10:37:49 freenas afpdr8812: INTERNAL ERROR: Signal 10 in pid 8812 (2.2.0)
Sep 11 10:37:49 freenas afpdr8812: ===============================================================
Sep 11 10:37:49 freenas afpdr8815: AFP3.3 Login by victorhooi
Sep 11 10:37:49 freenas afpdr8815: afp_disconnect: trying primary reconnect
Sep 11 10:37:49 freenas afpdr1767: Reconnect: no childr8812
Sep 11 10:37:54 freenas afpdr8815: afp_disconnect: primary reconnect failed
Sep 11 10:37:55 freenas cnid_metadr1765: 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 afpdr8815: transmit: Request to dbd daemon (db_dir /mnt/datastore/photos) timed out.
Sep 11 10:38:16 freenas afpdr8815: Reopen volume /mnt/datastore/photos using in memory temporary CNID DB.
Sep 11 10:40:01 freenas freenasr8829: 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

History

#1 Updated by Anonymous about 8 years ago

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.

#2 Updated by Anonymous about 8 years ago

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

#3 Updated by John - about 8 years ago

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?

#4 Updated by Anonymous about 8 years ago

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 freenasr1725: Executing: /usr/sbin/service ix-afpd quietstart
Oct  3 23:03:18 freenas freenasr1725: 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 freenasr1725: Executing: /usr/sbin/service dbus forcestop
Oct  3 23:03:18 freenas freenas: Stopping dbus.
Oct  3 23:03:18 freenas avahi-daemonr44614: Disconnected from D-Bus, exiting.
Oct  3 23:03:18 freenas freenasr1725: 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 freenasr1725: 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 freenasr1725: 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-daemonr44923: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Oct  3 23:03:18 freenas freenasr1725: 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_metadr44938: Set syslog logging to level: LOG_NOTE
Oct  3 23:03:19 freenas r44940: Set syslog logging to level: LOG_NOTE
Oct  3 23:03:19 freenas afpdr44941: AFP/TCP started, advertising xxx.xxx.xxx.xxx:548 (2.2.0)
Oct  3 23:03:21 freenas freenasr1725: Executing: /bin/pgrep -F /var/run/afpd.pid afpd
Oct  3 23:03:23 freenas afpdr44941: 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 afpdr45035: AFP3.3 Login by nobody
Oct  3 23:05:04 freenas afpdr45035: AFP logout by nobody
Oct  3 23:05:04 freenas afpdr45035: dsi_stream_read: len:0, unexpected EOF
Oct  3 23:05:04 freenas afpdr45035: afp_over_dsi: client logged out, terminating DSI session
Oct  3 23:05:04 freenas afpdr45035: AFP statistics: 0.37 KB read, 0.36 KB written
Oct  3 23:05:13 freenas afpdr45079: AFP3.3 Login by pierre
Oct  3 23:05:22 freenas cnid_metadr44939: 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 afpdr45079: transmit: Request to dbd daemon (db_dir /mnt/pool/sharename) timed out.
Oct  3 23:05:43 freenas afpdr45079: Reopen volume /mnt/pool/sharename using in memory temporary CNID DB.

#5 Updated by John - about 8 years ago

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?

#6 Updated by Anonymous about 8 years ago

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.

#7 Updated by John - about 8 years ago

  • Status changed from Closed to Investigation

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.

#8 Updated by John - almost 8 years ago

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?

#9 Updated by Anonymous almost 8 years ago

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)..

#10 Updated by Anonymous almost 8 years ago

(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)..

#11 Updated by Anonymous almost 8 years ago

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

#12 Updated by Anonymous almost 8 years ago

  • Status changed from Investigation to Closed

I've tried again with a 8.0.3-BETA2/i386 (not available for public consumption yet, but will be available tomorrow after I poke around with some stuff a bit more) 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).

#13 Updated by Anonymous almost 8 years ago

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

#14 Updated by cjoy - over 6 years ago

  • Status changed from Closed to Investigation

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
afpdr5152: 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
afpdr5152: transmit: Request to dbd daemon (db_dir /mnt/BAR) timed out.
kernel: pid 5241 (cnid_dbd), uid 1002: exited on signal 11
afpdr5152: enumerate(vid:4, did:2, name:'.'): error adding dir: 'SomeFolder'
cnid_metadr2271: 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

#15 Updated by Josh Paetzel over 6 years ago

  1. 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.

#16 Updated by Anonymous over 6 years ago

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

#17 Updated by cjoy - over 6 years ago

Replying to [comment:17 jpaetzel]:

  1. 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!

#18 Updated by Anonymous over 6 years ago

  • Status changed from Investigation to Closed

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.

Also available in: Atom PDF