error sending TCP data >4KB

F

Friedrich Volkmann

After upgrading my hardware, my OS (FBSD 9 -> 10.1 STABLE) and most applications, I have now problems sending big files.

Thunderbird and Claws-Mail report an error when I try to send mails greater than ~4KB.
Mutt manages to send bigger mails for some reason. Its behaviour does not seem reproducible, but when I include a attachment with ~110 KB, it finally fails too.

It's not just a freebsd-ports issue, because when I use ftp(1) to upload a file, I run into the same problem. An error is reported when I upload a file >= 4045 bytes, but not when it's <= 4044 bytes.

Now for some details:

1. OS:
Code: 
~$ uname -a
FreeBSD daemon.volki.at 10.1-STABLE FreeBSD 10.1-STABLE #3 r278696: Mon Feb 16 20:35:07 CET 2015  root@daemon.volki.at:/usr/obj/usr/src10/sys/CU06  i386

2. Firewall:
I can't turn it off (because I need NAT), but ifpw show does not list any package drops during tests.

3. Thunderbird:
Messagebox content:
Code: 
Sending of message failed.
The message could not be sent because connecting to SMTP server smtp.sil.at failed. The server may be unavailable or is refusing SMTP connections. Please verify that your SMTP server settings are correct and try again, or contact the server administrator.

Last lines of Thunderbird's logs:
Code: 
676335744[28561280]: SMTP Send: DATA
676335744[28561280]: SMTP entering state: 0
676335744[28561280]: SMTP Response: 354 Enter message, ending with "." on a line by itself
676335744[28561280]: SMTP entering state: 7
676335744[28561280]: SMTP entering state: 8

(The log stops here. For smaller mails which succeed, there would follow:
[INDENT]676335744[28561280]: SMTP Send: .
676335744[28561280]: SMTP entering state: 0
676335744[28561280]: SMTP Response: 250 OK id=1YNhHV-0001wc-92
etc.[/INDENT]
)
tcpdump while sending:
Code: 
~# tcpdump -i em0
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on em0, link-type EN10MB (Ethernet), capture size 65535 bytes
13:33:02.957195 IP 192.168.0.130.36281 > 199.16.157.105.https: Flags [.], ack 4164621351, win 1034, length 0
13:33:02.997780 IP 192.168.0.130.53104 > cns1.sil.at.domain: 53827+ PTR? 130.0.168.192.in-addr.arpa. (44)
13:33:03.008105 IP cns1.sil.at.domain > 192.168.0.130.53104: 53827 NXDomain 0/1/0 (93)
13:33:03.008533 IP 192.168.0.130.32963 > cns1.sil.at.domain: 23524+ PTR? 105.157.16.199.in-addr.arpa. (45)
13:33:03.043341 IP cns1.sil.at.domain > 192.168.0.130.32963: 23524 NXDomain 0/1/0 (115)
13:33:03.084979 IP 199.16.157.105.https > 192.168.0.130.36281: Flags [.], ack 1, win 1701, options [nop,nop,TS val 815232786 ecr 39266817], length 0
13:33:04.044503 IP 192.168.0.130.36959 > cns1.sil.at.domain: 51697+ PTR? 1.232.129.213.in-addr.arpa. (44)
13:33:04.054435 IP cns1.sil.at.domain > 192.168.0.130.36959: 51697 1/0/0 PTR cns1.sil.at. (69)
13:33:06.966538 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags , seq 3743625216, win 65535, options [mss 1460,nop,wscale 6,sackOK,TS val 39321405 ecr 0], length 0
13:33:06.977669 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [S.], seq 1583288881, ack 3743625217, win 5792, options [mss 1420,sackOK,TS val 554007782 ecr 39321405,nop,wscale 7], length 0
13:33:06.977686 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [.], ack 1, win 1034, options [nop,nop,TS val 39321416 ecr 554007782], length 0
13:33:07.093192 IP 192.168.0.130.41239 > cns1.sil.at.domain: 12293+ PTR? 209.12.59.86.in-addr.arpa. (43)
13:33:07.106767 IP cns1.sil.at.domain > 192.168.0.130.41239: 12293 1/0/0 PTR smtp.sil.at. (68)
13:33:07.175048 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 1:198, ack 1, win 46, options [nop,nop,TS val 554007831 ecr 39321416], length 197
13:33:07.199555 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [P.], seq 1:23, ack 198, win 1034, options [nop,nop,TS val 39321638 ecr 554007831], length 22
13:33:07.209502 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [.], ack 23, win 46, options [nop,nop,TS val 554007840 ecr 39321638], length 0
13:33:07.213696 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 198:376, ack 23, win 46, options [nop,nop,TS val 554007841 ecr 39321638], length 178
13:33:07.273199 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [P.], seq 23:64, ack 376, win 1034, options [nop,nop,TS val 39321712 ecr 554007841], length 41
13:33:07.282436 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 376:384, ack 64, win 46, options [nop,nop,TS val 554007859 ecr 39321712], length 8
13:33:07.282527 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [P.], seq 64:90, ack 384, win 1034, options [nop,nop,TS val 39321722 ecr 554007859], length 26
13:33:07.333206 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [.], ack 90, win 46, options [nop,nop,TS val 554007871 ecr 39321722], length 0
13:33:07.739973 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 384:398, ack 90, win 46, options [nop,nop,TS val 554007973 ecr 39321722], length 14
13:33:07.740087 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [P.], seq 90:96, ack 398, win 1034, options [nop,nop,TS val 39322179 ecr 554007973], length 6
13:33:07.749803 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [.], ack 96, win 46, options [nop,nop,TS val 554007975 ecr 39322179], length 0
13:33:07.750750 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 398:454, ack 96, win 46, options [nop,nop,TS val 554007975 ecr 39322179], length 56
13:33:07.974371 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 398:454, ack 96, win 46, options [nop,nop,TS val 554008032 ecr 39322179], length 56
13:33:07.974392 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [.], seq 96:1504, ack 454, win 1034, options [nop,nop,TS val 39322414 ecr 554007975], length 1408
13:33:08.063704 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [.], ack 1504, win 68, options [nop,nop,TS val 554008053 ecr 39322414], length 0
13:33:08.063712 IP bad-len 0
13:33:08.106555 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [.], ack 2912, win 91, options [nop,nop,TS val 554008065 ecr 39322503], length 0
13:33:08.106564 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [F.], seq 4192, ack 454, win 1034, options [nop,nop,TS val 39322546 ecr 554008065], length 0
13:33:08.137592 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [.], ack 4192, win 113, options [nop,nop,TS val 554008072 ecr 39322503], length 0
13:33:08.139291 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [P.], seq 454:484, ack 4193, win 113, options [nop,nop,TS val 554008073 ecr 39322546], length 30
13:33:08.139302 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [R], seq 3743629409, win 0, length 0
13:33:08.139549 IP smtp.sil.at.smtp > 192.168.0.130.50210: Flags [F.], seq 484, ack 4193, win 113, options [nop,nop,TS val 554008073 ecr 39322546], length 0
13:33:08.139553 IP 192.168.0.130.50210 > smtp.sil.at.smtp: Flags [R], seq 3743629409, win 0, length 0
^C
36 packets captured
39 packets received by filter
0 packets dropped by kernel
This does not give me much of a clue, because I am no TCP adept.

4. Claws-Mail:
The log reads:
Code: 
[13:45:40] SMTP> MAIL FROM:<...>
[13:45:40] SMTP< 250 OK
[13:45:40] SMTP> RCPT TO:<...>
[13:45:40] SMTP< 250 Accepted
[13:45:40] SMTP> DATA
[13:45:40] SMTP< 354 Enter message, ending with "." on a line by itself
*** Error occurred while sending the message.
There was also a some message about a "Permission denied" error in sock_write(), but I don't get this anymore. The sock_write() function in session.c indirectly calls read(), although the "Permission denied" (EACCES) error is set by socket(), not read(), according to the man page.

5. ftp:
With a file of size = 4044 bytes:
Code: 
ftp> put test.txt
local: test.txt remote: test.txt
229 Extended Passive mode OK (|||58243|)
150 Accepted data connection
100% |******************************************************************************|  4044  183.65 MiB/s  00:00 ETA
226-File successfully transferred
226 0.113 seconds (measured here), 35.04 Kbytes per second
4044 bytes sent in 00:00 (34.76 KiB/s)
With a file of size = 4045 bytes:
Code: 
ftp> put test.txt
local: test.txt remote: test.txt
229 Extended Passive mode OK (|||33241|)
150 Accepted data connection
  0% |  |  0  0.00 KiB/s  --:-- ETAftp: Writing to network: Permission denied
  0% |  |  -1  0.00 KiB/s  --:-- ETA
226-File successfully transferred
226 0.535 seconds (measured here), 7.38 Kbytes per second
Surprisingly, the whole file is transferred in spite of the error.
Code: 
ftp> ls
229 Extended Passive mode OK (|||58271|)
150 Accepted data connection
drwxr-xr-x  2 2106  site1607  4096 Feb 17 14:21 .
drwxr-xr-x  4 2106  site1607  4096 Feb 17 12:30 ..
-rw-r--r--  1 2106  site1607  4045 Feb 17 14:21 test.txt
226-Options: -a -l
226 3 matches total
But when I put a file bigger than 32768 bytes, the file is truncated:
Code: 
ftp> !ls -l test_10xsize.txt
-rw-r--r--  1 root  operator  40450 17 Feb 14:25 test_10xsize.txt
ftp> put test_10xsize.txt
local: test_10xsize.txt remote: test_10xsize.txt
229 Extended Passive mode OK (|||15992|)
150 Accepted data connection
  0% |  |  0  0.00 KiB/s  --:-- ETAftp: Writing to network: Permission denied
  0% |  |  -1  0.00 KiB/s  --:-- ETA
226-File successfully transferred
226 2.472 seconds (measured here), 12.94 Kbytes per second
ftp> ls
229 Extended Passive mode OK (|||3590|)
150 Accepted data connection
drwxr-xr-x  2 2106  site1607  4096 Feb 17 14:27 .
drwxr-xr-x  4 2106  site1607  4096 Feb 17 12:30 ..
-rw-r--r--  1 2106  site1607  4045 Feb 17 14:21 test.txt
-rw-r--r--  1 2106  site1607  32768 Feb 17 14:28 test_10xsize.txt
-rw-r--r--  1 2106  site1607  8090 Feb 17 14:24 test_doublesize.txt
So there seem to be two limits:
The error message appears for data > 1044 bytes, and the truncation occurs at 32768 bytes.

Any ideas?
 
Thanks to Juanitou for reformatting. (I didn't do it myself because of my upload issues.)

Friedrich Volkmann said:
There was also a some message about a "Permission denied" error in sock_write(), but I don't get this anymore.
Click to expand...

Meanwhile I found out. It's console output:
Code: 
** (claws-mail:77283): WARNING **: sock_write: Permission denied


** (claws-mail:77283): WARNING **: [15:54:33] Error occurred while sending the message.
 
I see 10.1-STABLE. Just as a sanity check, are kernel/userland in sync. Does file /bin/sh match uname -a?

After that, are you only using an Intel NIC? I've seen this PR, PR 193802, for Intel NIC's with segmentation offload. However, I don't believe that the way symptoms are are manifesting matches up with this being the issue. You can always try an ifconfig em0 -tso to see if it helps.

Does netstat -i list any hits on the errors or drops columns?
 
junovitch said:
I see 10.1-STABLE. Just as a sanity check, are kernel/userland in sync. Does file /bin/sh match uname -a?
Click to expand...
Yes.
After that, are you only using an Intel NIC? I've seen this PR, PR 193802, for Intel NIC's with segmentation offload. However, I don't believe that the way symptoms are are manifesting matches up with this being the issue. You can always try an ifconfig em0 -tso to see if it helps.
Click to expand...
That's it. Thanks!

Code: 
em0: <Intel(R) PRO/1000 Network Connection 7.4.2> port 0xf080-0xf09f mem 0xf7f00000-0xf7f1ffff,0xf7f3c000-0xf7f3cfff irq 20 at device 25.0 on pci0
em0: Using an MSI interrupt
em0: Ethernet address: 44:8a:5b:9a:79:ee

After ifconfig em0 -tso everything seems to work.

Does netstat -i list any hits on the errors or drops columns?
Click to expand...
No:
Code: 
#  netstat -i
Name  Mtu Network  Address  Ipkts Ierrs Idrop  Opkts Oerrs  Coll
re0  1500 <Link#1>  00:15:8a:00:28:da  400  0  0  400  0  0
re0  - 10.0.0.0  daemon  0  -  -  0  -  -
lo0  16384 <Link#2>  10  0  0  10  0  0
lo0  - your-net  localhost  10  -  -  10  -  -
lo0  - localhost  ::1  0  -  -  0  -  -
lo0  - fe80::1%lo0  fe80::1%lo0  0  -  -  0  -  -
em0  1500 <Link#3>  44:8a:5b:9a:79:ee  133089  0  0  98370  0  0
em0  - 192.168.0.0  192.168.0.130  2324  -  -  2050  -  -
 
That is very strange. I wouldn't have guessed that the permission denied issues would be one of the result of the offload issue. It wouldn't hurt to post some of the symptoms you have seen into the bug report to aid anybody else looking at the same issue.
 
You must log in or register to reply here.
Back
Top