Opened 22 months ago
Closed 18 months ago
#624 closed defect (worksforme)
apfd Errors On FreeNAS 8 8r7209 Nightly Build; Time Machine Backups Fail
| Reported by: | BobCochran | Owned by: | |
|---|---|---|---|
| Priority: | major | Milestone: | 8.0.1-RELEASE |
| Component: | Backend | Version: | |
| Keywords: | apfd | Cc: |
Description
While attempting to create a Time Machine backup (under OS X Lion 10.7.0) using a new FreeNAS volume with an AFP share configured, I experienced these errors:
Start of Observed FreeNAS Errors Issued On Machine Console
August 17 21:10:39 freenas apfd[4132]: bind(fd, (struct sockaddr *)&address, address_length) failed: Address already in use
August 17 21:14:17 freenas apfd[4132]: Reading IPC header failed (-1 of 14 bytes read): resource temporarily unavailable
August 17 21:14:17 freenas last message repeated 2 times
FreeNAS system them becomes unresponsive. Cannot log out of the web GUI. Cannot use the console on the FreeNAS 8 machine. Server basically crashes. Time Machine, in this case, issued an error dialog box stating that the backup failed due to a network error.
End of Observed FreeNAS Errors Issued On Machine Console
Attachments (10)
Change History (39)
comment:1 Changed 22 months ago by behold5469
comment:2 Changed 22 months ago by BobCochran
I meant to file this for component afpd. I apologize for naming it wrong. Alexander's comments stimulated me to change the userid of the user I had defined on FreeNAS to 585 instead of 502. The gid remains '20' for 'staff'.
Afpd continues to fail on nightly build 8r7209 even with this change.
comment:3 Changed 22 months ago by delphij
Hi,
I've ported a few revisions from netatalk git that "looks interesting" but I'm not very sure if that would fix your problem, could you please help me to do some test?
In order to do the test you would need to do the following:
- login as root via ssh, or select "shell" from the console menu;
- mount -u /
- (optional; cd /mnt/tank or anywhere you like, then) pkg_create -jb netatalk-2.2.0_4,1
- pkg_delete -f netatalk-2.2.0_3,1
- pkg_add -r http://people.freebsd.org/~delphij/misc/netatalk-2.2.0_4,1.tbz
Then you need to restart AFP service or reboot the system.
Please let me know if this helps or not, thanks!
comment:4 Changed 22 months ago by behold5469
Delphij,
I've given you're comments a test run. Here the following:
a) pgk_create fails:
freenas# pkg_create -jb netatalk-2.2.0_4,1 pkg_create: can't find package 'netatalk-2.2.0_4,1' installed!
b) pkg_delete works, pgk_add returns some messages. I don't think that this matters
freenas# pkg_add -r http://people.freebsd.org/~delphij/misc/netatalk-2.2.0_4,1.tbz Fetching http://people.freebsd.org/~delphij/misc/netatalk-2.2.0_4,1.tbz... Done. pkg_add: command '[ ! -f /usr/local/etc/AppleVolumes.default ] && cp /usr/local/etc/AppleVolumes.default.dist /usr/local/etc/AppleVolumes.default' failed pkg_add: command '[ ! -f /usr/local/etc/AppleVolumes.system ] && cp /usr/local/etc/AppleVolumes.system.dist /usr/local/etc/AppleVolumes.system' failed
c) startup of afpd. It seems as if pgrep is executed twice? The first time the bind seems to fail, maybe thats why it is executed a second time?
Aug 19 10:39:57 freenas afpd[2725]: AFP/TCP started, advertising 192.168.2.57:548 (2.2.0) Aug 19 10:39:58 freenas freenas[1736]: Executing: /bin/pgrep -F /var/run/afpd.pid afpd Aug 19 10:39:58 freenas afpd[2725]: bind(fd, (struct sockaddr *)&address, address_length) failed: Address already in use Aug 19 10:39:58 freenas freenas[1736]: Executing: /bin/pgrep -F /var/run/afpd.pid afpd
d) TM Backup doesn't fail and return the IPC header failure. Just the bind failure.
Since it worked for me in the past somebody needs to verify this aswell, but it seems as if the new version doesn't break anything else :-)
Im running off the nightly build 8r7209
Regards
Alexander
comment:5 Changed 22 months ago by delphij
Hi,
I've backported another patch. Could you please try the following and report if that fixed your problem?
- login as root via ssh, or select "shell" from the console menu;
- mount -u /
- (optional; cd /mnt/tank or anywhere you like, then) pkg_create -jb netatalk-2.2.0_4,1
- pkg_delete -f netatalk-2.2.0_4,1
- pkg_add -r http://people.freebsd.org/~delphij/misc/netatalk-2.2.0_4,1.tbz
Thanks in advance!
comment:6 Changed 21 months ago by BobCochran
Hello, I am following this thread with the greatest interest and will apply your latest patch tomorrow morning (Eastern Standard Time) to build 8r7209, the same one Alexaneder is. I will report results.
Regards
comment:7 Changed 21 months ago by delphij
Hi, Bob,
If you want to build from source, use this patch: http://people.freebsd.org/~delphij/misc/netatalk.diff
I haven't make it into the same shape of what's expected in FreeNAS tree yet (since I don't personally own a Mac to test it). It adds a few patches so it's trivial to add these patches manually.
comment:8 Changed 21 months ago by BobCochran
Hi Delphij,
I applied your netatalk-2.2.0_4,1.tbz patch and have a backup running on my wife's MacBook? Air (which is running OS X 10.7.1). I am very hopeful that the backup will succeed. So far it has backed up more than 4 Gb of data (out of 69 Gb...this is the first backup to a FreeNAS volume) and that is doing pretty good.
My FreeNAS boot disk is a 4 Gb USB flash drive. I suspect I may need to add a small SATA hard drive to give myself a real "user" home directory that actually has space that I can use for downloading stuff like your netatalk.diff patch. I did try a wget on netatalk-2.2.0_4,1.tbz but the download failed with an error message saying the system is out of space. Perhaps it is best for me to install FreeNAS to a true hard drive. Or just have a /home directory on a separate volume.
Thanks
Bob Cochran
Greenbelt, Maryland
comment:9 Changed 21 months ago by BobCochran
The backup of the MacBook? Air failed. During all the previous backup attempts, Time Machine would issue an error message. In this case Time Machine quit without any error message at all. Remember the MacBook? Air is running OS X 10.7.1. I checked the FreeNAS server and found the console frozen -- it would not accept keyboard input. I have rebooted the FreeNAS server. I may go out and get myself a small SATA drive so I can have a home directory and start working with your netatalk.diff patch.
Bob
Changed 21 months ago by behold5469
Changed 21 months ago by behold5469
Changed 21 months ago by behold5469
Changed 21 months ago by behold5469
Changed 21 months ago by behold5469
Changed 21 months ago by behold5469
comment:10 Changed 21 months ago by behold5469
Delphij, Bob,
here my current status. I've taken the current version from delphij and did a full vanilla backup of my wifes macbook (10.7.1). The backup is around 70gb of data. This was done running on following VMware
Hostname freenas.local OS Version FreeBSD 8.2-RELEASE-p2 Platform Intel(R) Core(TM) i7-2620M CPU @ 2.70GHz Memory 1008MB System Time Tue Aug 23 10:56:37 CEST 2011 Uptime 10:56AM up 2:17, 2 users Load Average 0.00, 0.36, 1.67 FreeNAS Build FreeNAS-8r7209-amd64
I created a blank 100GB VMware disk, did a single ZFS filesystem on it and exported the complete Volume as a TM-Volume.
Something that doesn't work with Delphijs netatalk build is the guest access (I assume that some path is compiled static into this build), so access was via www/www.
Following is the output of /var/log/message:
freenas# tail -f /var/log/messages Aug 23 08:46:14 freenas cnid_metad[3618]: Set syslog logging to level: LOG_NOTE Aug 23 08:46:14 freenas [3620]: Set syslog logging to level: LOG_NOTE Aug 23 08:46:14 freenas afpd[3621]: AFP/TCP started, advertising 192.168.2.57:548 (2.2.0) Aug 23 08:46:14 freenas freenas[1747]: Executing: /bin/pgrep -F /var/run/afpd.pid afpd Aug 23 08:46:15 freenas afpd[3621]: bind(fd, (struct sockaddr *)&address, address_length) failed: Address already in use Aug 23 08:46:35 freenas afpd[3634]: AFP3.3 Login by www Aug 23 08:46:40 freenas afpd[3634]: AFP logout by www Aug 23 08:46:40 freenas afpd[3634]: dsi_stream_read: len:0, unexpected EOF Aug 23 08:46:40 freenas afpd[3634]: afp_over_dsi: client logged out, terminating DSI session Aug 23 08:46:40 freenas afpd[3634]: AFP statistics: 0.66 KB read, 0.52 KB written Aug 23 08:47:25 freenas afpd[3651]: AFP3.3 Login by www Aug 23 08:48:10 freenas afpd[3668]: AFP3.3 Login by www Aug 23 08:48:10 freenas afpd[3668]: AFP logout by www Aug 23 08:48:10 freenas afpd[3668]: AFP statistics: 1.28 KB read, 1.10 KB written Aug 23 08:48:10 freenas afpd[3668]: done Aug 23 08:48:27 freenas afpd[3678]: AFP3.3 Login by www Aug 23 08:48:27 freenas cnid_dbd[3679]: Set syslog logging to level: LOG_NOTE Aug 23 08:55:59 freenas ntpd[1518]: kernel time sync status change 2001 Aug 23 09:51:06 freenas afpd[3651]: select: Invalid argument Aug 23 09:51:06 freenas afpd[3651]: dsi_stream_read: len:-1, Invalid argument Aug 23 09:51:07 freenas afpd[4471]: AFP3.3 Login by www Aug 23 09:51:08 freenas afpd[4471]: afp_disconnect: trying primary reconnect Aug 23 09:51:08 freenas afpd[3621]: Reconnect: transfering session to child[3651] Aug 23 09:51:08 freenas afpd[3621]: Reconnect: killing new session child[4471] after transfer Aug 23 09:51:08 freenas afpd[3651]: afp_dsi_transfer_session: succesfull primary reconnect Aug 23 09:51:10 freenas afpd[4471]: afp_disconnect: primary reconnect succeeded Aug 23 10:07:11 freenas afpd[3651]: select: Invalid argument Aug 23 10:07:11 freenas afpd[3651]: dsi_stream_read: len:-1, Invalid argument Aug 23 10:17:14 freenas afpd[3651]: select: Invalid argument Aug 23 10:17:14 freenas afpd[3651]: dsi_stream_read: len:-1, Invalid argument Aug 23 10:17:15 freenas afpd[4992]: AFP3.3 Login by www Aug 23 10:17:15 freenas afpd[4992]: afp_disconnect: trying primary reconnect Aug 23 10:17:15 freenas afpd[3621]: Reconnect: transfering session to child[3651] Aug 23 10:17:15 freenas afpd[3621]: Reconnect: killing new session child[4992] after transfer Aug 23 10:17:15 freenas afpd[3651]: afp_dsi_transfer_session: succesfull primary reconnect Aug 23 10:17:17 freenas afpd[4992]: afp_disconnect: primary reconnect succeeded Aug 23 10:21:48 freenas afpd[3651]: select: Invalid argument Aug 23 10:21:48 freenas afpd[3651]: dsi_stream_read: len:-1, Invalid argument Aug 23 10:39:50 freenas afpd[3651]: select: Invalid argument Aug 23 10:39:50 freenas afpd[3651]: dsi_stream_read: len:-1, Invalid argument Aug 23 10:39:52 freenas afpd[5438]: AFP3.3 Login by www Aug 23 10:39:52 freenas afpd[5438]: afp_disconnect: trying primary reconnect Aug 23 10:39:52 freenas afpd[3621]: Reconnect: transfering session to child[3651] Aug 23 10:39:52 freenas afpd[3621]: Reconnect: killing new session child[5438] after transfer Aug 23 10:39:52 freenas afpd[3651]: afp_dsi_transfer_session: succesfull primary reconnect Aug 23 10:39:54 freenas afpd[5438]: afp_disconnect: primary reconnect succeeded Aug 23 10:47:15 freenas afpd[3678]: AFP logout by www Aug 23 10:47:15 freenas afpd[3678]: AFP statistics: 71427438.20 KB read, 135720.69 KB written Aug 23 10:47:15 freenas afpd[3678]: done
As you can see everything went fine. During the backup process there were some afp_ dsi_transfer and afp_disconnects (what ever those means). But the backup never stopped/failed/hanged etc. Additionally you see some afp_stream_read, but no stop/fail/hang of the TM-Backup.
Basically what I can say is that everything works great.
Additionally I've attached the report images that show my system load.
So from my side I would say everything is Ok. Only thing that I noticed is that the system load goes up/down. I would have expected it to stay constant since the backup is the only thing running, but this might have to do with the VMWare.
Regards
Alexander
Edit: when browsing timemachine I receive an error "the operation can't be completed". But I can still browse and restore files. This error only happens once (when browsing multiple times the TM-Volume)
I've also backupd data twice now. Browsing TM I see the different timestamps and everything looks OK apart from the previously mentioned item.
Alexander
comment:11 Changed 21 months ago by BobCochran
Alexander,
Thanks for posting this. All my attempts to date have been with guest access, in my wife's case as user 'organizer' group 'staff'. I have never been clear on what guest access means or how to use it properly.
I will try www/www tonight as you have.
I have also been looking hard at my actual hardware setup. I wanted to see if my server box is set up per the "sucesssful" hardware guidelines for FreeNAS. To me my hardware seems a bit of the 'slap it together' variety as opposed to a carefully planned and researched configuration. I just put FreeNAS on a USB stick, connected two hard drives to convenient SATA jacks on the motherboard, changed the BIOS to boot the USB disk, and let it boot. FreeNAS comes right up. Then I use only 1 of the 2 hard drives.
I notice a lot of people seem to be using either SAS controllers or what seems to be some form of SCSI and RAID controller. I did just recently order a Dell Perc 5 "0HN359 SAS 5 PCIE Adapter Card USC-51 MY412" card, and need to get an SFF-8484 to SATA Host csrd.
Bob
comment:12 Changed 21 months ago by BobCochran
comment:13 Changed 21 months ago by BobCochran
The backup of my wife's computer has again failed even with AFP settings as above. Time Machine (on 10.7.1) transferred more than 5 Gb of data then it quit with two dialog boxes giving error messages. I did take screenshots of the dialog boxes but had a problem pasting them into an email to myself.
Perhaps my settings are wrong?
I will try to reproduce the error and do a better job of saving error messages.
Bob
comment:14 Changed 21 months ago by behold5469
Bob,
FreeNAS is quite "forgiving" and light on the hardware side. If everything is detected it basically should work. Naturally if you want to maximize performace etc you would need to research a bit more. Saying this I don't think its your hardware (unless you have too little memory or disk space).
The screenshot looks ok, but please post the following:
a) After reboot the file /var/log/messages
b) your system config (as detected by FreeNAS) from the system tab in the webgui
c) How is the Volume setup for TM? Is it a ZFS mirror/raidz/single disk etc? How big is the disk? The command "df" shows how much is available.
d) Since your box becomes unresponsive, please SSH from a terminal program onto your box and before the TM-Backup do a "tail -f /var/log/messages" and capture the output. This will allows you to copy the messages even if the box get unresponsive
Alexander
Changed 21 months ago by BobCochran
/var/log/messages file from Bob Cochran's FreeNAS server, following reboot (See Alexander's request)
comment:15 Changed 21 months ago by BobCochran
Hi Alexander,
Thank you for getting back to me. I have attached the /var/log/messages file to this ticket as requested. Also, the system information you request is shown below.
Item c) -- the backup volume is set up as a ZFS single disk. No RAID, no raidz, and to the best of my knowledge it is not a mirror. Here is the df:
freenas# df /mnt/mymac1
Filesystem 1K-blocks Used Avail Capacity Mounted on
mymac1 957873855 18814467 939059387 2% /mnt/mymac1
I will ssh into the FreeNAS server now and tail the /var/log/messages file and attempt to do a backup of my wife's system again.
Regards,
Bob
comment:16 Changed 21 months ago by BobCochran
Hi Alexander,
I better confess what will be obvious on examination of the /var/log/messages -- I gave a fake user name for my wife above. Her user name is 'rachel' and group 'staff'. I started a fresh backup attempt a few minutes ago and I'm seeing from the tail of /var/log/messages that afpd is reporting a login by 'rachel':
Aug 24 19:44:09 freenas afpd[2975]: AFP3.3 Login by rachel
Strange that it doesn't login as 'www' the way your messages show. Perhaps I need to remove user 'rachel' from my FreeNAS system to fix the problem? However the backup is still running and I'm just guessing at this point.
Thanks a lot for your help!
Bob
comment:17 Changed 21 months ago by BobCochran
The backup has again failed. The tail of /var/log/messages, in contrast to what you show above, has only a few lines of output:
Aug 24 19:36:28 freenas freenas[1709]: Executing: /bin/pgrep -F /var/run/sshd.pid sshd
Aug 24 19:44:09 freenas afpd[2975]: AFP3.3 Login by rachel
Aug 24 19:44:26 freenas cnid_dbd[2976]: Set syslog logging to level: LOG_NOTE
The FreeNAS server becomes unresponsive:
deafeng33:Pictures bobc$ ping -c3 192.168.1.69
PING 192.168.1.69 (192.168.1.69): 56 data bytes
Request timeout for icmp_seq 0
ping: sendto: No route to host
Request timeout for icmp_seq 1
My wife's MacBook? responds to pings:
deafeng33:Pictures bobc$ ping -c3 192.168.1.5
PING 192.168.1.5 (192.168.1.5): 56 data bytes
64 bytes from 192.168.1.5: icmp_seq=0 ttl=64 time=135.636 ms
64 bytes from 192.168.1.5: icmp_seq=1 ttl=64 time=55.333 ms
64 bytes from 192.168.1.5: icmp_seq=2 ttl=64 time=78.145 ms
I'm going to try removing the user rachel from the FreeNAS server and trying the backup again.
Thanks for all your help!
Bob
comment:18 Changed 21 months ago by BobCochran
I removed the user 'rachel' from my FreeNAS system, and the backup would not start at all.
"Time Machine could not complete the backup. The backup disk is not available."
OK
I get these log messages:
freenas# tail -f /var/log/messages
Aug 24 21:11:05 freenas root: /etc/rc: WARNING: failed precmd routine for vmware_guestd
Aug 24 21:11:05 freenas freenas[1267]: Popen()ing: sysctl -b kern.geom.confxml
Aug 24 21:11:06 freenas freenas[1366]: Popen()ing: sysctl -b kern.geom.confxml
Aug 24 21:11:06 freenas ntpd[1462]: ntpd 4.2.4p5-a (1)
Aug 24 21:11:06 freenas avahi-daemon[1673]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Aug 24 21:11:07 freenas cnid_metad[1683]: Set syslog logging to level: LOG_NOTE
Aug 24 21:11:07 freenas [1685]: Set syslog logging to level: LOG_NOTE
Aug 24 21:11:07 freenas afpd[1686]: AFP/TCP started, advertising 192.168.1.69:548 (2.2.0)
Aug 24 21:11:07 freenas kernel: re0: link state changed to UP
Aug 24 21:11:15 freenas ntpd[1463]: time reset +0.611586 s
Aug 24 21:17:21 freenas freenas[1709]: Executing: /usr/sbin/pw userdel "rachel"
Aug 24 21:17:21 freenas freenas[1709]: Executing: /usr/sbin/service ix-passwd quietstart
Aug 24 21:17:21 freenas freenas[1709]: Executing: /usr/sbin/service ix-aliases quietstart
Aug 24 21:17:21 freenas freenas[1709]: Executing: /usr/sbin/service ix-samba quietstart
Aug 24 21:17:21 freenas freenas: tdbsam_open: Converting version 0.0 database to version 4.0.
Aug 24 21:17:21 freenas freenas: tdbsam_convert_backup: updated /var/etc/private/passdb.tdb file.
Aug 24 21:17:21 freenas freenas: Importing account for root...ok
Aug 24 21:17:21 freenas freenas[1709]: Executing: /usr/sbin/service samba reload
Aug 24 21:17:21 freenas freenas: Performing sanity check on Samba configuration: OK
Aug 24 21:17:22 freenas freenas[1709]: Executing: /bin/pgrep -F /var/run/samba/smbd.pid smbd
Aug 24 21:18:49 freenas afpd[2598]: AFP statistics: 0.06 KB read, 0.06 KB written
Aug 24 21:18:49 freenas afpd[2599]: AFP statistics: 0.06 KB read, 0.06 KB written
I wonder if I have permissions for the backup volume set up incorrectly?
Thanks for all your help!
Bob
comment:19 Changed 21 months ago by behold5469
Hi Bob,
thanks for the information can you tray a few other things:
a) connect with your mac to the AFP share and write a file on it (just to test if you can write).
b) do a "ls -l /mnt" and a "ls -l /mnt/mymac1"
c) After you removed "rachel" from the FreeNAS system, you have to setup Timemachine on the mac again, since it needs to reconnect as www.
d) On the TM-Volume (I assume its /mnt/mymac1) there should be a file "your wifes mac name".sparsebundle . Is it there ?
What I find strange in your log file is the following:
Aug 24 19:08:38 freenas [1685]: Set syslog logging to level: LOG_NOTE Aug 24 19:08:38 freenas afpd[1686]: AFP/TCP started, advertising 192.168.1.69:548 (2.2.0) Aug 24 19:08:39 freenas kernel: re0: link state changed to UP
it seems as if your network card comes up after AFP has started? Is your IP address fixed or DHCP ?
But first try to have the Mac connect directly with the share so that we see that afpd works or not.
Alexander
comment:20 Changed 21 months ago by BobCochran
Hi Alexander,
Thank you for the advice and also the heads up about my network card. I will work on the items you indicate tomorrow and get back to you. I'm on the East Coast of the USA and Hurricane Irene is whirring steadily closer, we are under either a tropical storm warning or a hurricane watch depending on which National Hurricane Center advisory one reads.
I am using a fixed IP address for my FreeNAS server. I can think of two possible sources of trouble with my network card. The first is that it is faulty and needs replacing. Or: maybe the card (which is actually integrated on the motherboard) can't handle huge data streams over 4 Gb? Or: the routing is being done by a Verizon FIOS router and I don't know if that router has trouble with moving data streams in excess of 4 Gb.
Thanks for all your help!
Bob
comment:21 Changed 21 months ago by BobCochran
Hi Alexander,
In answer to your questions:
a) On my Mac, I am able to connect to the AFP share and write files to it.
b) Here are the results of ls -l /mnt' and ls -l /mnt/mymac1':
freenas# ls -l /mnt
total 6
drwxrwxr-x 2 root operator 512 Aug 27 18:28 .snap
-rw-r--r-- 1 root wheel 5 Aug 17 00:00 md_size
drwxrwxrwx 8 root wheel 10 Aug 27 18:56 mymac1
freenas# ls -al /mnt/mymac1
total 1949
drwxrwxrwx 8 root wheel 10 Aug 27 18:56 .
drwxr-xr-x 4 root wheel 512 Aug 27 18:29 ..
drwxr-xr-x 2 root wheel 12 Aug 27 18:55 .AppleDB
drwxrwxrwx 2 502 wheel 3 Aug 17 21:12 .AppleDesktop?
drwxrwxrwx 2 502 wheel 5 Aug 27 18:56 .AppleDouble?
-rw-rw-rw- 1 bobc wheel 12292 Aug 27 18:56 .DS_Store
drwxrwxrwx 3 502 wheel 3 Aug 17 21:12 Network Trash Folder
drwxrwxrwx 3 502 wheel 3 Aug 17 21:12 Temporary Items
drwxrwxrwx 4 563 wheel 9 Aug 24 20:14 rachel channon???s MacBook? Air.sparsebundle
-rw-rw-rw- 1 bobc wheel 1886134 Aug 10 17:05 tips.pdf
Notice the tips.pdf file was written by me when I connected to the Apple share a few minutes ago. I copied this file from my home directory on my Mac to the afp share on the FreeNAS.
c) I set up Time Machine on my wife's MacBook? Air again to connect as user 'www'. I was a bit confused for a moment when I couldn't connect, then I realized that afp was expecting a password for user 'www', so I used the FreeNAS 8 web GUI to set a password for the user.
d) Yes there is a sparse bundle directory:
drwxrwxrwx 4 563 wheel 9 Aug 24 20:14 rachel channon???s MacBook? Air.sparsebundle
On the Macbook, under Apple --> System Preferences --> Sharing, the computer name is given as "Rachel Channon's MacBook? Air". I recall reading a web article stating that the apostrophe in (for example) "Channon's" can cause a problem with Time Machine backups, so I have renamed the computer to 'rcmbp6' or something similar.
I am now attempting a fresh backup after this change. I will see if afpd quits or the FreeNAS server for whatever reason becomes unresponsive.
Thanks
Bob
comment:22 Changed 21 months ago by BobCochran
Hi Alexander,
My backup attempt transmitted more data to the FreeNAS volume than previous backups did, at 7+ Gb, but the backup stopped unexpectedly again. On my Mac I saw a quickly-appearing and disappearing window that the 'server connection interrupted'. I am wondering if my network hardware is at fault. For example the integrated network card on my server.
Thanks again for all your help!
Bob
comment:23 Changed 21 months ago by BobCochran
Hi Alexander,
I forgot to post my tail of /var/log/messages:
freenas# tail -f /var/log/messages
Aug 27 18:46:03 freenas freenas[1709]: Executing: /usr/sbin/service ix-samba quietstart
Aug 27 18:46:03 freenas freenas: tdbsam_open: Converting version 0.0 database to version 4.0.
Aug 27 18:46:03 freenas freenas: tdbsam_convert_backup: updated /var/etc/private/passdb.tdb file.
Aug 27 18:46:03 freenas freenas: Importing account for root...ok
Aug 27 18:46:03 freenas freenas: Importing account for bobc...ok
Aug 27 18:46:03 freenas freenas[1709]: Executing: /usr/sbin/service samba reload
Aug 27 18:46:03 freenas freenas: Performing sanity check on Samba configuration: OK
Aug 27 18:46:03 freenas freenas[1709]: Executing: /bin/pgrep -F /var/run/samba/smbd.pid smbd
Aug 27 18:55:21 freenas afpd[2680]: AFP3.3 Login by bobc
Aug 27 18:55:21 freenas cnid_dbd[2682]: Set syslog logging to level: LOG_NOTE
Aug 27 19:07:32 freenas afpd[2745]: AFP statistics: 0.06 KB read, 0.06 KB written
Aug 27 19:07:32 freenas afpd[2746]: AFP statistics: 0.06 KB read, 0.06 KB written
Aug 27 19:10:32 freenas afpd[2761]: AFP statistics: 0.06 KB read, 0.06 KB written
Aug 27 19:10:32 freenas afpd[2762]: AFP statistics: 0.06 KB read, 0.06 KB written
Aug 27 19:11:46 freenas afpd[2775]: AFP statistics: 0.51 KB read, 0.38 KB written
Aug 27 19:13:27 freenas freenas[1709]: Popen()ing: /usr/sbin/pw usermod "www" -h 0
Aug 27 19:13:27 freenas freenas[1709]: Popen()ing: /usr/local/bin/smbpasswd -s -a "www"
Aug 27 19:13:27 freenas freenas[1709]: Popen()ing: /usr/local/bin/pdbedit -w www
Aug 27 19:13:27 freenas freenas[1709]: Executing: /usr/sbin/service ix-passwd quietstart
Aug 27 19:13:27 freenas freenas[1709]: Executing: /usr/sbin/service ix-aliases quietstart
Aug 27 19:13:27 freenas freenas[1709]: Executing: /usr/sbin/service ix-samba quietstart
Aug 27 19:13:28 freenas freenas: tdbsam_open: Converting version 0.0 database to version 4.0.
Aug 27 19:13:28 freenas freenas: tdbsam_convert_backup: updated /var/etc/private/passdb.tdb file.
Aug 27 19:13:28 freenas freenas: Importing account for root...ok
Aug 27 19:13:28 freenas freenas: Importing account for www...ok
Aug 27 19:13:28 freenas freenas: Importing account for bobc...ok
Aug 27 19:13:28 freenas freenas[1709]: Executing: /usr/sbin/service samba reload
Aug 27 19:13:28 freenas freenas: Performing sanity check on Samba configuration: OK
Aug 27 19:13:28 freenas freenas[1709]: Executing: /bin/pgrep -F /var/run/samba/smbd.pid smbd
Aug 27 19:14:03 freenas afpd[3094]: AFP3.3 Login by www
Aug 27 19:14:04 freenas afpd[3094]: AFP logout by www
Aug 27 19:14:04 freenas afpd[3094]: AFP statistics: 1.32 KB read, 1.18 KB written
Aug 27 19:14:04 freenas afpd[3094]: done
Aug 27 19:14:23 freenas afpd[3097]: AFP3.3 Login by www
Write failed: Broken pipe
Thanks for all your help!
Bob Cochran
comment:24 Changed 21 months ago by behold5469
Hi Bob,
It looks as if it might be your network card. Since your log file showed strangely the late "up" of your network card, the error message during your backup and the "broken pipe" in you log file.
Give it a try with a spare card. That might be the solution.
Cheers
Alexander
comment:25 Changed 21 months ago by BobCochran
Hi Alexander,
I will definitely use a new network adapter. I have a TRENDnet Gigabit PCI Adapter Card TEG-PCITXR on the way and should get it Tuesday. I will let you know if this solves the issue.
I think I got off very lightly from hurricane Irene. We got lots of rain and only moderately high winds, my house and yard are undamaged, and we lost power for only 23 hours.
Thanks for all your help!
Bob Cochran
comment:26 Changed 21 months ago by BobCochran
Hi Alexander,
My Trendnet network card arrived yesterday and I installed it. I deleted the config file for re0 and configured the new network card (re1) with the ipv4 address I had been using all along. I then attempted another backup of my wife's MacBook? Air. I noticed from the /var/log/messages file that the link state for re1 was changed to UP after afpd started. Then AFP3.3 recorded a login from www as expected. Then Time Machine transfers > 10 Gb of data from the MacBook? to the FreeNAS volume, and the backup stops suddenly, long before it is done, and a "broken pipe" message is the last item that appears in /var/log/messages, just as before. So it looks like the network card is some help -- but there is still a problem here.
I should explain that all the data is going through a Actiontec brand, model MI424-WR Rev F router/FiOS modem supplied by Verizon as part of my fiber optic (FiOS) installation. In the case of my wife's MacBook? the connection to the Actiontec router is wireless. The router is about 1 year old. From the router, data goes by wire to a Dell PowerConnect? model 2716 network switch which is several years old. From the switch, it goes by wire to the Trendnet network card in my FreeNAS server. The motherboard itself is an MSI 890GXM-G65.
I've done plenty of 4-6 Gb downloads with the router to various boxes and laptops, but have never tried doing 68 Gb wireless data transfers over my network with this until now.
Is there anything in this hardware setup that could cause my network backups to fail? The new network card is a 32 bit PCI adapter card; does this mean there is a limit to the amount of data the card can manage? Could my RAM or motherboard components be causing the backups to fail? Would the wifi network card in the MacBook? Air have trouble with that amount of data?
Is there a way I can test the ability of the FreeNAS server to manage very large chunks of data, say more than 30 Gb?
I'm also willing to postal mail the USB drive containing my FreeNAS server if you would like to review the overall configuration.
Thanks
Bob Cochran
comment:27 Changed 21 months ago by behold5469
Hi Bob,
sorry to hear that the new network card didn't work out as planned (you got a bit more of data, but not the full backup). I have no idea concerning the FiOS modem. Looking at your hardware I have no idea what it could be (since everything looks fine).
It would make no sense of you sending me your usb drvie (I sit in Germany), since basically it works for me and I cannont comment on your FiOS, switch Infrastructur.
I would suggest that you close the ticket and take this to the forums (forums.freenas.org). Maybe somebody has similar hardware/problems.
See you in the forums.
Regards
Alexander
comment:28 Changed 18 months ago by gcooper
Closing this issue based on the last comment. I didn't see any issues with my Macbook running Snow Leopard when I tested this functionality over my Airport a few months ago.
That being said, I am working on gaining access to a Mac with Lion (probably will get it in the next week or so) and will definitely verify whether or not this functionality works in the next week or so with netatalk 2.2.1 (this will be available in FreeNAS 8.0.3+).
comment:29 Changed 18 months ago by gcooper
- Resolution set to worksforme
- Status changed from new to closed










I've gotten this error as well (TM doesn't fail on my side). I've checked the internet, it seems as if it known
-> http://www.readynas.com/forum/viewtopic.php?f=28&t=55205
-> http://sourceforge.net/tracker/index.php?func=detail&aid=3378532&group_id=8642&atid=108642
It seems as if for some it helped if the UID of the user backing up via TM is different then the user being used to backup(on FreeNAS). But it seems as if it doesn't help everybody.
The second link is to the netatalk bug list on sourceforge mentioning that this should be fixed in 2.2.1
Regards
Alexander