Upgrade takes an hour to complete due to repeated 30-second FTP timeout

[mmorearty]

On my FreeBSD server (hosted by ISP pair.com), the built-in upgrade feature of WordPress takes at least an hour to complete. I debugged the problem, and it turns out to be due to a mismatch between the FTP responses WordPress is expecting vs. the FTP responses FreeBSD is actually sending.

(Attached is a dump of phpinfo() from the machine on which I am seeing this problem.)

Steps to reproduce:

1. Clean WordPress installation on FreeBSD
2. Go to the Dashboard, then click Updates
3. Click "Re-install Automatically"
4. Enter hostname, user name, and password; leave Connection Type as FTP; click Proceed

Actual result:
The update eventually completes successfully, but it takes an extraordinarily long time -- at least an hour.

Expected result:
Should finish much more quickly than that.

I debugged this, and here is what is happening:

• My PHP installation ends up using the "ftpsockets" filesystem to do the update. (If necessary, you can force the use of that filesystem for testing purposes by adding "define('FS_METHOD', 'ftpsockets')" to your wp-config.php.)

• Every time anyone calls WP_Filesystem_ftpsockets->exists() to see if a file exists, that function calls ftp->is_exists(), which calls ftp->file_exists() in wp-admin/includes/class-ftp.php.

• That function tests for the existence of a file by sending the FTP command "RNFR" (rename from) across the FTP connection. If the RNFR command succeeds, then the assumption is that the remote file exists; if it fails with an error message, then the assumption is that the remote file does not exist.

• Immediately after sending the RNFR command, if the RNFR succeeded, then is_exists() calls abort(), to send an ABOR -- I'm guessing this is intended to abort the rename.

• However, this is where things go bad. FreeBSD replies to the ABOR command with "426 Nothing to abort". WordPress's abort() function then attempts to read one more line, but there is nothing to read, so that read attempt times out after 30 seconds.

Here is the way the whole "exists()" conversation looks when it works correctly on my Mac:

PUT > RNFR /Users/mike/Sites/wordpress/ 
GET < 350 File exists, ready for destination name 
PUT > ABOR
GET < 225 ABOR command successful. 
Remote file /Users/mike/Sites/wordpress/ exists

And here is the way the conversation looks when it times out on my FreeBSD machine:

PUT > RNFR /usr/www/users/morearty/blog2/ 
GET < 350 You may attempt to rename /usr/www/users/morearty/blog2. 
PUT > ABOR 
GET < 426 Nothing to abort.
[... 30-second delay here, as abort() attempts to read one more line ... and then:]
abort: Read failed

[mmorearty]

phpinfo() from the FreeBSD machine where I am seeing this problem

[mmorearty]

Note the explicit check for error code 426 in function abort() in wp-admin/includes/class-ftp.php:

function abort() {
    if(!$this->_exec("ABOR", "abort")) return FALSE;
    if(!$this->_checkCode()) {
        if($this->_code!=426) return FALSE;
        if(!$this->_readmsg("abort")) return FALSE;
        if(!$this->_checkCode()) return FALSE;
    }
    return true;
}

The way this is written, if ABOR returns any error code other than 426, abort() just returns FALSE; but if it sees 426, it tries to read one more line (the call to _readmsg()) before returning FALSE. On my FreeBSD machine, though, there is nothing more to read.

[mmorearty]

If it matters, when I manually FTP in to my server, this is the message printed by FTP:

220 morearty.com NcFTPd Server (licensed copy) ready.

So, it sounds like NcFTPd is the FTP server software being used.

[dd32]

So, it sounds like NcFTPd is the FTP server software being used.

Cheers for that additional detail, it'll make testing/patching this a lot easier.

I'll see if i can get a VM instance of BSD running with it sometime over the coming months before 3.1 and see if i can get it working as well as not conflicting with other common setups..

It does seem strange that it'd ignore the 426 error code specifically..

[mmorearty]

I was able to reproduce the problem by downloading and running the Mac version of NcFTPd. FreeBSD was not necessary to reproduce.

I'm just guessing here, but I think perhaps the reason the 426 error code has special handling is because of the wording in the ​FTP RFC. It says that when an FTP service command is already in progress and an ABOR command is received, the server will send a 426 followed by a 226:

"the server aborts the FTP service in progress and closes the data connection, returning a 426 reply to indicate that the service request terminated abnormally. The server then sends a 226 reply, indicating that the abort command was successfully processed."

[kencaron]

Was hoping to see this resolved for 3.1

I am having the same issues on a client that is hosting through pair.com

Any updates on this? Would much prefer to use the automatic systems in place than an FTP client.

[Denis-de-Bernardy]

See #17301

[dd32]

Went on a bit of a hunt, the latest version of ncFTPd is still affected by this.

After a lot of trial and error, and looking up the sources for other FTP Client software, I couldn't work out how others handle this scenario. So much so, that I could not find a FTP server that sends 226 after a 426. All servers seem to send 226 for a success, 426 for a failure, couldn't find one that sends both (although, they DO exist).

I've come up with an alternative though, switch from using the FTP class is_exists / file_exists() method, and instead, use nlist() instead (the same as we do for the PHP Ftp Extension), effectively bypassing the buggy code in question.

This seems to work flawlessly for me.

[dd32]

In 25274:

WP_Filesystem: FTP Sockets: Avoid using the file_exists() / is_exists() / exists() PemFTP functionality as it's buggy on ncFTPd servers, switching to listing the file instead which is what we use for the FTP Extension transport. Fixes #14049

[mmorearty]

Terrific, thanks dd32!