kern/100172: Transfer of large file fails with host is down message

Stefan Moeding sm at kill-9.net
Wed Jul 12 18:10:22 UTC 2006


>Number:         100172
>Category:       kern
>Synopsis:       Transfer of large file fails with host is down message
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Wed Jul 12 18:10:15 GMT 2006
>Closed-Date:
>Last-Modified:
>Originator:     Stefan Moeding <sm at kill-9.net>
>Release:        FreeBSD 6.1-STABLE i386
>Organization:
>Environment:
System: FreeBSD elan.setuid.de 6.1-STABLE FreeBSD 6.1-STABLE #7: Fri Jul  7 21:29:43 CEST 2006     root at elan.setuid.de:/usr/obj/usr/src/sys/ELAN  i386
System: FreeBSD eclat.setuid.de 6.1-STABLE FreeBSD 6.1-STABLE #0: Sat Jul  8 19:39:21 CEST 2006     root at eclat.setuid.de:/usr/obj/usr/src/sys/ECLAT  i386

Use a network interface with a second address as alias.

>Description:

I'm experiencing network failures during the transfer of large files
(>500MB).  Initially I've seen failures with my Amanda backups, but
I've checked different transfer protocols (NFS, scp, ftp, rsync) and
I'm unable to transfer a larger file.  Transfering the file from a
FreeBSD Samba server to a Win2K host is also not possible.  The error
messages always gives "Write failed: Host is down".

This happens at different times during the transfer.  Sometimes I'm
able to copy 500MB over the network while the next time it breaks
after 50MB.  Strangly enough the failure only happens when sending the
file into one direction.  The same host can receive the large file
without any error.  In the meantime I've used different network cards
(tx, fxp, xl, em) without any improvement.

The hosts are connected with a switched 100MB ethernet.  All the hosts
are using a customized kernel without INET6.  Otherwise no unusual
configuration (no netgraph, no bridging, ...).  sysctl.conf or
loader.conf contain no additional setting.  The kernel configs can be
downloaded here:

http://www.kill-9.net/ELAN.txt
http://www.kill-9.net/ECLAT.txt

>How-To-Repeat:

Using tcpdump for analysis revealed something that doesn't seem to be
a coincidence.  I can reproduce the failure now using the following
recipe:

I'm using two boxes with 6.1-STABLE but I've seen this when I was
running 6.0-STABLE as well.  Both machines have one network interface
with one IP address and they are connect over 100MB switched ethernet.
In this setup host eclat will be the sending host where the problem
occurs.  Start by initiating a large transfer from eclat to the local
hgost (esprit in my case):

esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date

This should run till eternity.  The date command will show the exact
time when the transfer breaks later.

Now start tcpdump on the sending side to monitor ARP requests:

eclat# tcpdump -vv -i dc0 arp
tcpdump: listening on dc0, link-type EN10MB (Ethernet), capture size 96 bytes
13:38:04.001409 arp who-has esprit.setuid.de tell eclat.setuid.de
13:38:04.001568 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
13:58:00.000763 arp who-has esprit.setuid.de tell eclat.setuid.de
13:58:00.001267 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)

This shows updates roughly every 20 minutes (this matches to
net.link.ether.inet.max_age).  During all this time the transfer
continues to run.

Now simply activate an IP alias on the interface of the sending system:

eclat# ifconfig -a
dc0: flags=8943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST> mtu 1500
	options=8<VLAN_MTU>
	inet 192.168.9.33 netmask 0xffffff00 broadcast 192.168.9.255
	ether 00:08:c7:03:88:12
	media: Ethernet autoselect (100baseTX <full-duplex>)
	status: active
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> mtu 16384
	inet 127.0.0.1 netmask 0xff000000 

eclat# date; ifconfig dc0 inet 10.10.10.10 alias
Sun Jul  9 14:02:06 CEST 2006


>From this moment the ARP request will show every 5 minutes:

14:02:06.550107 arp who-has 10.10.10.10 tell 10.10.10.10
14:02:54.473083 arp who-has esprit.setuid.de tell eclat.setuid.de
14:02:54.473245 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:07:53.472684 arp who-has esprit.setuid.de tell eclat.setuid.de
14:07:53.472866 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:12:52.474264 arp who-has esprit.setuid.de tell eclat.setuid.de
14:12:52.474389 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:17:51.474580 arp who-has esprit.setuid.de tell eclat.setuid.de
14:17:51.474708 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:22:50.473488 arp who-has esprit.setuid.de tell eclat.setuid.de
14:22:50.473605 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:27:49.474955 arp who-has esprit.setuid.de tell eclat.setuid.de
14:27:49.475124 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:32:48.475158 arp who-has esprit.setuid.de tell eclat.setuid.de
14:32:48.475326 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:37:47.540016 arp who-has esprit.setuid.de tell eclat.setuid.de
14:37:47.540166 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:42:46.663505 arp who-has esprit.setuid.de tell eclat.setuid.de
14:42:46.663703 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:47:45.474979 arp who-has esprit.setuid.de tell eclat.setuid.de
14:47:45.475167 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)
14:52:44.476128 arp who-has esprit.setuid.de tell eclat.setuid.de
14:52:44.476299 arp reply esprit.setuid.de is-at 00:02:b3:2a:45:5a (oui Unknown)

At the same time I start getting the network failures at exactly the
time when the 5 minute ARP timer is due.  While this doesn't seem to
happen all the time, it doesn't look like a coincidence to me.
Restarting the transfer a couple of times I got the following output:

esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:07:53 CEST 2006
esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:17:51 CEST 2006
esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:27:49 CEST 2006
esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:32:48 CEST 2006
esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:37:47 CEST 2006
esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:42:46 CEST 2006
esprit% (ssh eclat cat /dev/zero ) | cat >/dev/null ; date
Connection to eclat.setuid.de closed by remote host.
Sun Jul  9 14:52:44 CEST 2006

Notice how the time of the error message matches the timestamp from
the ARP requests.

>Fix:

A fix is unknown.

As a workaround I'm using a static ARP entry on the sending box.
>Release-Note:
>Audit-Trail:
>Unformatted:


More information about the freebsd-bugs mailing list