Frequent disconnects in PureFTPd (MySQL); unable to complete large binary file upload

[cbj4074]

I'm experiencing an issue with PureFTPd, but I don't know that the issue is ISPConfig-specific. In any event, it can't hurt to ask, can it?

I'm attempting to upload a sizable file (a little over 700MB) to the server, via FTPs (I'm not sure the TLS part matters), but my FTP client is disconnected constantly throughout the process; every minute or two. My client attempts to resume the upload each time it is disconnected.

Here is a log excerpt (this was before I enabled verbose logging). The XXX.XXX.XXX.XXX entries represent my public (Internet) IP address.

Nov  7 02:41:36 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 02:41:37 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 02:41:37 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 02:41:37 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.
Nov  7 02:41:42 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 02:41:43 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 02:41:43 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 02:41:43 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.
Nov  7 02:41:48 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 02:41:49 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 02:41:49 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 02:41:49 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [NOTICE] Restarting at 638943232
Nov  7 02:43:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.
Nov  7 02:43:56 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 02:43:56 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 02:43:56 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 02:43:56 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.
Nov  7 02:44:02 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 02:44:02 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 02:44:02 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 02:44:02 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.
Nov  7 02:44:07 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 02:44:08 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 02:44:08 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 02:44:08 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [NOTICE] Restarting at 638943232

When the log reflects "[NOTICE] Restarting at 638943232", does it mean to say that the file upload is being resumed at byte offset 638943232?

Once the upload progress reaches a certain point (the exact byte offset changes with each new upload attempt), the file is deleted from the server (I see no evidence in the log that the client is requesting the deletion).

Then, the following sequence is repeated in syslog (this is after I enabled verbose debugging):

Nov  7 08:57:11 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 08:57:11 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [DEBUG] Command [auth] [TLS]
Nov  7 08:57:11 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 08:57:11 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [DEBUG] Command [user] [ftpuser]
Nov  7 08:57:11 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [DEBUG] Command [pass] [<*>]
Nov  7 08:57:11 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 08:57:11 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [pbsz] [0]
Nov  7 08:57:11 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [prot] [P]
Nov  7 08:57:11 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [opts] [UTF8 ON]
Nov  7 08:57:11 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [cwd] [/web]
Nov  7 08:57:12 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [type] [I]
Nov  7 08:57:12 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [pasv] []
Nov  7 08:57:12 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [rest] [606683136]
Nov  7 08:57:12 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [NOTICE] Restarting at 606683136
Nov  7 08:57:12 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [stor] [large-file.zip]
Nov  7 08:57:42 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.
Nov  7 08:57:48 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] New connection from XXX.XXX.XXX.XXX
Nov  7 08:57:49 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [DEBUG] Command [auth] [TLS]
Nov  7 08:57:49 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] SSL/TLS: Enabled TLSv1/SSLv3 with DHE-RSA-AES256-SHA, 256 secret bits cipher
Nov  7 08:57:49 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [DEBUG] Command [user] [ftpuser]
Nov  7 08:57:50 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [DEBUG] Command [pass] [<*>]
Nov  7 08:57:50 example.com pure-ftpd: (?@XXX.XXX.XXX.XXX) [INFO] ftpuser is now logged in
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [pbsz] [0]
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [prot] [P]
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [opts] [UTF8 ON]
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [cwd] [/web]
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [type] [I]
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [DEBUG] Command [port] [10,0,1,112,213,58]
Nov  7 08:57:50 example.com pure-ftpd: (ftpuser@XXX.XXX.XXX.XXX) [INFO] Logout.

One can see that the FTP client appears to switch from Passive Mode to Active Mode automatically, and, of course, Active Mode will not work (due to firewalls on both ends).

PureFTPd is configured such that /etc/pure-ftpd/conf/PassivePortRange contains "40110 40210".

Also, the Firewall is configured to allow TCP connections to the passive port range, as defined above.

Here is the firewall configuration (via ISPConfig Status):

iptables -S (ipv4)
-P INPUT DROP
-P FORWARD DROP
-P OUTPUT ACCEPT
-N INT_IN
-N INT_OUT
-N PAROLE
-N PUB_IN
-N PUB_OUT
-N fail2ban-apache
-N fail2ban-apache-badbots
-N fail2ban-apache-noscript
-N fail2ban-apache-overflows
-N fail2ban-dovecot
-N fail2ban-postfix
-N fail2ban-pure-ftpd-mysql
-N fail2ban-sasl
-N fail2ban-ssh
-N fail2ban-ssh-ddos
-A INPUT -p tcp -m multiport --dports 21,20,990,989 -j fail2ban-pure-ftpd-mysql
-A INPUT -p tcp -m multiport --dports 80,443 -j fail2ban-apache-badbots
-A INPUT -p tcp -m multiport --dports 80,443 -j fail2ban-apache
-A INPUT -p tcp -m multiport --dports 25,465,143,220,993,110,995 -j fail2ban-sasl
-A INPUT -p tcp -m multiport --dports 25,465 -j fail2ban-postfix
-A INPUT -p tcp -m multiport --dports 22 -j fail2ban-ssh
-A INPUT -p tcp -m multiport --dports 80,443 -j fail2ban-apache-overflows
-A INPUT -p tcp -m multiport --dports 22 -j fail2ban-ssh-ddos
-A INPUT -p tcp -m multiport --dports 25,465,143,220,993,110,995 -j fail2ban-dovecot
-A INPUT -p tcp -m multiport --dports 80,443 -j fail2ban-apache-noscript
-A INPUT -d 127.0.0.0/8 ! -i lo -p tcp -j DROP
-A INPUT -m state --state RELATED,ESTABLISHED -j ACCEPT
-A INPUT -i lo -j ACCEPT
-A INPUT -s 224.0.0.0/4 -j DROP
-A INPUT -i eth+ -j PUB_IN
-A INPUT -i ppp+ -j PUB_IN
-A INPUT -i slip+ -j PUB_IN
-A INPUT -i venet+ -j PUB_IN
-A INPUT -i bond+ -j PUB_IN
-A INPUT -j DROP
-A FORWARD -m state --state RELATED,ESTABLISHED -j ACCEPT
-A FORWARD -j DROP
-A OUTPUT -o eth+ -j PUB_OUT
-A OUTPUT -o ppp+ -j PUB_OUT
-A OUTPUT -o slip+ -j PUB_OUT
-A OUTPUT -o venet+ -j PUB_OUT
-A OUTPUT -o bond+ -j PUB_OUT
-A INT_IN -p icmp -j ACCEPT
-A INT_IN -j DROP
-A INT_OUT -p icmp -j ACCEPT
-A INT_OUT -j ACCEPT
-A PAROLE -j ACCEPT
-A PUB_IN -p icmp -m icmp --icmp-type 3 -j ACCEPT
-A PUB_IN -p icmp -m icmp --icmp-type 0 -j ACCEPT
-A PUB_IN -p icmp -m icmp --icmp-type 11 -j ACCEPT
-A PUB_IN -p icmp -m icmp --icmp-type 8 -j ACCEPT
-A PUB_IN -p tcp -m tcp --dport 20 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 21 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 22 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 25 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 53 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 80 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 110 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 143 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 443 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 465 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 587 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 993 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 995 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 3306 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 8080 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 8081 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 8443 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 10000 -j PAROLE
-A PUB_IN -p tcp -m tcp --dport 40110:40210 -j PAROLE
-A PUB_IN -p udp -m udp --dport 53 -j ACCEPT
-A PUB_IN -p udp -m udp --dport 3306 -j ACCEPT
-A PUB_IN -p icmp -j DROP
-A PUB_IN -j DROP
-A PUB_OUT -j ACCEPT
-A fail2ban-apache -j RETURN
-A fail2ban-apache-badbots -j RETURN
-A fail2ban-apache-noscript -j RETURN
-A fail2ban-apache-overflows -j RETURN
-A fail2ban-dovecot -j RETURN
-A fail2ban-postfix -j RETURN
-A fail2ban-pure-ftpd-mysql -j RETURN
-A fail2ban-sasl -j RETURN
-A fail2ban-ssh -j RETURN
-A fail2ban-ssh-ddos -j RETURN

I'm able to upload small binary files (e.g., 2MB in size) without issue, so the problem appears to be related to a resource-limit of some kind, whether that is a timeout, a file size limit, etc.

The FTP user was created via the ISPConfig interface and all of his resource limits therein are set to -1 (unlimited). Likewise, the ISPConfig client to which the FTP user is assigned is not constrained by resource limits in ISPConfig.

Any help with this is greatly appreciated. Thanks!

[falko]

Did you check if the Internet connection is stable?

Is this a physical server or a virtual machine?

How much RAM does it have?

[cbj4074]

Thanks for the reply, Falko.

The Internet connection seems to be stable; five of us use the connection all day, every day, without issue. I was able to upload the same file to Dropbox without observing any anomalous behavior, too.

The server is a virtual machine, of the mediaTemple (ve) variety, which uses openvz.

The server has 2GB of physical memory, 600MB to 700MB of which is free when this occurs.

Due to the lack of capability-switching support in openvz, I had to follow Till's instructions from http://www.faqforge.com/linux/contro...ities-enabled/ to build and install pureFTPd in the first place.

Is it worth trying to update pureFTPd to the latest version?

Thanks again!

[till]

In a first test you can e.g. check if the issue is related to the network connction of the server or the server itself or FTP by trying to upload the same wile with sftp, sftp is a ssh based protocol which is implemented as part of the ssh daemon. (you need a sh user in ispconfig for that or use your root user for this test). If the test failes as well, then it is a general server problem and not related directly to pure-ftpd. If the upload succeeds, then it is worth trying to update pure-ftpd.

[cbj4074]

Thanks, Till. That's a great idea.

I was able to upload the entire file on the first try when using sFTP, so the problem does indeed seem to be pureFTPd-specific.

I'll work on upgrading pureFTPd next. I'm stuck on Ubuntu 10.04 for a while, so I'll have to build from source to install the latest version. Maybe I'll detail the process in a "How To" post, as I have not found clear instructions for building pureFTPd from source on Debian or Ubuntu systems (without using pre-baked source .deb packages).

Stay tuned!

[cbj4074]

Well, installing the latest version of pureFTPd that will run on my system was a lot easier than I had expected.

Because I followed your instructions from http://www.faqforge.com/linux/contro...ities-enabled/ when I installed pureFTPd initially, I already had the debian directory from the latest Ubuntu package for my system (10.04 Lucid).

I was able to download the most recent source from http://download.pureftpd.org/pub/pure-ftpd/releases/ and copy the debian directory from the obsoleted Ubuntu package into the new source directory and build a package that is specific to my OS and has all of the exact same configuration options.

Unfortunately, it appears that the source code for pure-ftpd-1.0.36 yields a pure-ftpd_1.0.24-1 package on my system, but at least I have upgraded from 1.0.21 to 1.0.24.

The package installed without any problems, so I will try re-uploading this 700MB file and see what happens.

[falko]

I think this could have to do with memory (e.g. the system could leave out of memory during the upload). Do you have munin installed so that you can check this?

If this is an OpenVZ system: what is the output of

cat /proc/user_beancounters

?

[cbj4074]

Hey, guys, I really appreciate your continued assistance on this issue.

Here's the output, Falko:

# cat /proc/user_beancounters
Version: 2.5
       uid  resource                     held              maxheld              barrier                limit              failcnt
    77910:  kmemsize                 41141872             41176540            228000000            240000000                    0
            lockedpages                     0                    0                 2400                 2400                    0
            privvmpages                284190               283957               772014               812646                 7620
            shmpages                     4603                 4603                60000                60000                  358
            dummy                           0                    0  9223372036854775807  9223372036854775807                    0
            numproc                       186                  186                 1200                 1200                    0
            physpages                  143905               143674                    0           2147483647                    0
            vmguarpages                     0                    0               524288           2147483647                    0
            oomguarpages               143906               143675  9223372036854775807           2147483647                    0
            numtcpsock                     77                   77                 4000                 4000                    0
            numflock                       11                   11                 1000                 1100                    0
            numpty                          1                    1                  200                  200                    0
            numsiginfo                      0                    1                 1024                 1024                    0
            tcpsndbuf                 2496824              2496824             20000000             40000000                    0
            tcprcvbuf                 1261568              1261568             20000000             40000000                    0
            othersockbuf               475096               477704             10000000             20000000                    0
            dgramrcvbuf                     0                    0             20000000             20000000                    0
            numothersock                  253                  253                 4000                 4000                    0
            dcachesize                2104859              2107676             57000000             60000000                    0
            numfile                      8224                 8245                80000                80000                    0
            dummy                           0                    0                    0                    0                    0
            dummy                           0                    0                    0                    0                    0
            dummy                           0                    0                    0                    0                    0
            numiptent                     115                  115                  500                  500                    0

The server has at least 700MB memory free when I begin the upload; is it really possible that pureFTPd is consuming all of that memory to process a 700MB file upload?

[till]

The server has at least 700MB memory free when I begin the upload; is it really possible that pureFTPd is consuming all of that memory to process a 700MB file upload?

Thats possible, I guess that only a pure-ftpd dev might be able to asnwer this in detail.

Have you checked if the number in the failcnt column of the beancounters increases when a upload fails?

[cbj4074]

Hi, Till,

I watched htop's output during the upload process and memory usage didn't fluctuate at all. Granted, I was checking the usage visually only every 5-10 minutes, but I never saw it increase beyond 1200MB of 2000MB available (3015MB if virtual memory is included).

Also, I examined the failcnt column in the beancounter output before I started the upload and after the upload failed. The value did not change.

It seems strange that the FTP client becomes "stuck in a loop" immediately after the failure occurs. The client is then unable to resume the upload at all after the initial failure.

As stated in my first post, the client attempts to resume the transfer as frequently as possible after the initial failure occurs, but the client is disconnected immediately (within 1 second) after issuing the "stor" command. pureFTPd says nothing about why the client is disconnected; the log says only, "[INFO] Logout." No warnings, no errors, nothing.

I am trying this again with pureFTPd 1.0.24 (instead of 1.0.21) and will post the results...