PureFTP Error during write to data connection and --without-sendfile

[rking]

A user of ours is receiving the error:

450 Error during write to data connection

Note: Not "450 Error during write to data connection: Invalid Argument"

We've gone through all of the usual steps, check firewalls, check anti-virus software, binary vs. ASCII mode, the problem persists.

I found a suggestion on another thread and in the pure-ftpd documentation that sendfile support doesn't work properly on some kernels. We didn't have a problem on our CentOS 4 boxes, so I'm hoping the culprit is sendfile support on CentOS 5.

Any chance we could get a pure-ftpd RPM with the --without-sendfile flag compiled in? If worst comes to worst, we can try compiling from source.

I found a --without-sendfile compiled RPM on one of the old threads here in the forums. I'd prefer to not use an outdated RPM, but it 404'd anyways. Really I'm just grasping at straws here because we're unsure of what else could be causing this.

Oddly enough, it only happens with certain files and only happens on certain networks. We have tested this from many locations around the world. When tested from within the network, the files download fine. When tested from some external locations, it again works fine. When tested from others, it drops the connection. It's so sporradic, yet completely reproducable with the right file and location.

At the time of the error, the FTP client shows:

200 PORT command successful
150-Connecting to port 3824
150 2375.7 kbytes to download
Connection closed by remote host.

The FTP server shows:

May 29 20:43:34 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 150-Connecting to port 3824
May 29 20:43:34 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 150 2375.7 kbytes to download
May 29 20:46:20 SERVER pure-ftpd: (USER@IPADDRESS) [INFO] Transfer aborted
May 29 20:46:20 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 450 Error during write to data connection
May 29 20:46:20 SERVER pure-ftpd: (USER@IPADDRESS) [INFO] Logout.
May 29 20:46:20 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 450 Logout.

I've already enabled verbose logging and enabled FTP logging in syslog. No relevant information is presented other than the error in this thread title.

Any ideas?

On a lighter note, at one point while troubleshooting this issue, the FTP server told me:

200 PORT command successful
150-Connecting to port 3577
150-The computer is your friend. Trust the computer
150 2375.7 kbytes to download
Connection closed by remote host.

Silly Easter Eggs.

[rking]

Further information, the machine in question is running:

CentOS 5
2.6.18-53.1.21.el5PAE Kernel

[cpanelkenneth]

Just to verify: in all your tests you are connecting to the same FTP server?

[rking]

Through our tests we have actually tested on 3 different machines. All 3 machines have the same configuration and same hardware.

I'm currently in the process of setting up a 4th server to test with so I can try some custom compiles of pure-ftpd. The other 3 servers were live so I couldn't really tinker with the FTP service much. This server will not be using the PAE kernel. Hopefully I'll have some positive results.

[rking]

Same results on the new machine with the standard RPM, no love.

[rking]

No luck with pure-ftpd compiled --without-sendfile. I did get an strace this time:

FTP Log:

May 30 17:37:17 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 150 Connecting to port 1853
May 30 17:37:17 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 226-Options: -l
May 30 17:37:17 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 226 8 matches total
May 30 17:37:26 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] Command [port] [68,62,84,9,7,62]
May 30 17:37:26 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 200 PORT command successful
May 30 17:37:26 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] Command [retr] [FILENAME]
May 30 17:37:26 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 150-Connecting to port 1854
May 30 17:37:26 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 150 2390.8 kbytes to download
May 30 17:53:51 SERVER pure-ftpd: (USER@IPADDRESS) [INFO] Transfer aborted
May 30 17:53:51 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 450 Error during write to data connection
May 30 17:53:51 SERVER pure-ftpd: (USER@IPADDRESS) [INFO] Logout.
May 30 17:53:51 SERVER pure-ftpd: (USER@IPADDRESS) [DEBUG] 450 Logout.

strace output:

root@SERVER [/etc]# strace -p 4590
Process 4590 attached - interrupt to quit
write(3, "\21\376\312\374<\0\353\6_\3=\374\315\371\320\374\326\4\304\6\326\376\355\371\335\375\220\1\251\1\350\1"..., 5190) = 5190
munmap(0xb7d28000, 65536)               = 0
mmap2(NULL, 65536, PROT_READ, MAP_SHARED, 4, 0x100) = 0xb7d28000
write(3, "\7\21\10\243\t\262\r\n]\r\n\243\r\n{\r\n1\t\346\t\312\t\301\t\33\7\255\6f\6\5"..., 66124) = 20874
write(3, "\240\377\16\377`\0\216\1\23\0\234\377T\376\217\377z\0\306\0\240\377\212\376\354\3774\377\251\377\t\375"..., 45250) = -1 ETIMEDOUT (Connection timed out)
close(4)                                = 0
close(3)                                = 0
time(NULL)                              = 1212184431
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
send(2, "<94>May 30 17:53:51 pure-ftpd: ("..., 96, MSG_NOSIGNAL) = 96
setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
time(NULL)                              = 1212184431
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
send(2, "<95>May 30 17:53:51 pure-ftpd: ("..., 122, MSG_NOSIGNAL) = 122
write(1, "450 Error during write to data c"..., 43) = 43
setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
alarm(1800)                             = 85415
select(1, [0], NULL, NULL, {900, 0})    = 1 (in [0], left {900, 0})
read(0, "", 4112)                       = 0
time(NULL)                              = 1212184431
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
send(2, "<94>May 30 17:53:51 pure-ftpd: ("..., 87, MSG_NOSIGNAL) = 87
setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
time(NULL)                              = 1212184431
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2202, ...}) = 0
send(2, "<95>May 30 17:53:51 pure-ftpd: ("..., 92, MSG_NOSIGNAL) = 92
write(1, "450 Logout.\r\n", 13)         = 13
setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
exit_group(0)                           = ?
Process 4590 detached

The lines highlighted in red are where the server stalled. The FTP client displayed "Connection closed by remote host." and the server hung at the red highlighted lines for 15 minutes before timing out.

Looks like it might be time for a support ticket.

[rking]

We don't want to use proftpd, but for completeness, I figured I'd try. Same results.

[rking]

We ended up having a problem within our network and had to power cycle one of our core routers. Once the router came back up, we no longer had this issue on any of the servers I used for testing.