How to debug why PHP FTP won't work in PASV mode, when console FTP seems to work fine?

Question

I have a Docker Compose system for testing, in which I am doing end-to-end testing of a single-page web app. Several buttons in the web site will result in an FTP connection being initiated in one container (missive-transmitter), going to a test FTP server in another container (missive-testbox).

My FTP logic in PHP always uses "passive" mode, and I think this is causing the problem. I have created a script to run in missive-transmitter, which is a simplified version of the real thing. It is as follows, and is run directly from the console:

<?php
# ftptest.php

error_reporting(-1);
ini_set('display_errors', true);

$conn = ftp_connect('missive-testbox', 21);

$ok1 = ftp_login($conn, 'missive_test', 'password');
if (!$ok1)
{
    die("Cannot log in\n");
}

// *** Start problem section
$ok2 = ftp_pasv($conn, true);
if (!$ok2)
{
    die("Cannot switch to passive mode\n");
}
// *** End problem section

$info = ftp_systype($conn);
echo "Info: $info\n";

$ok3 = ftp_put($conn, 'ftptest.php', 'ftptest.php', FTP_ASCII);
if (!$ok3)
{
    die("Cannot send a file\n");
}

Now, if I remove the *** section (enabling passive mode) then the script will work. If I leave it in, I get this:

Info: UNIX

Warning: ftp_put(): php_connect_nonb() failed: Operation in progress (115) in /root/src/ftptest.php on line 23

Warning: ftp_put(): TYPE is now ASCII in /root/src/ftptest.php on line 23

Cannot send a file

I would like my FTP operation to work in PASV mode.

Oddly, if I install an FTP client then it seems to work in either active or passive modes, which is what I don't understand. On the missive-transmitter side:

~/src $ # This is the `sh` shell in `missive-transmitter`
~/src $ #
~/src $ # Install LFTP in Alpine environment
~/src $ apk add lftp
~/src $ lftp missive_test@missive-testbox
Password: 
lftp missive_test@missive-testbox:~> set ftp:passive-mode off         
lftp missive_test@missive-testbox:~> put ftptest.php       
457 bytes transferred                            
lftp missive_test@missive-testbox:/> set ftp:passive-mode on 
lftp missive_test@missive-testbox:/> put ftptest.php        
457 bytes transferred
lftp missive_test@missive-testbox:/>

Is PHP doing something differently, or am I not actually using PASV mode in the console client?

I have confirmed that both containers can ping each other from their respective sh consoles. They are on the same (custom) Docker network.

The missive-testbox Docker container is based on gists/pure-ftpd, so it should be configured correctly as far as I know.

Update

A useful point in an answer below is about how NAT might be making one side make a connection using the wrong IP address. However, the IP addresses appear to be on the same subnet, though I am no networking expert.

From missive-transmitter:

~ # ping missive-testbox
PING missive-testbox (172.19.0.2): 56 data bytes
64 bytes from 172.19.0.2: seq=0 ttl=64 time=0.076 ms

And from missive-testbox:

~ # ping missive-transmitter
PING missive-transmitter (172.19.0.4): 56 data bytes
64 bytes from 172.19.0.4: seq=0 ttl=64 time=0.119 ms

I think the fact they are both 172.19.0.x addresses means they should be able to see each other fully, though I am open to correction on that assumption.

Update 2

It has been suggested that getting some FTP client or server logs would be a good way to debug this. The client is pretty easy. Here are the same ops as above, but in LFTP's debug mode.

Active mode is first:

~/src # lftp -d missive_test@missive-testbox
Password: 
---- Resolving host address...
---- 1 address found: 172.19.0.2
lftp missive_test@missive-testbox:~> set ftp:passive-mode off
lftp missive_test@missive-testbox:~> put ftptest.php
---- Connecting to missive-testbox (172.19.0.2) port 21
<--- 220-Welcome to Pure-FTPd.
<--- 220-You are user number 1 of 5 allowed.
<--- 220-Local time is now 17:54. Server port: 21.
<--- 220-This is a private system - No anonymous login
<--- 220-IPv6 connections are also welcome on this server.
<--- 220 You will be disconnected after 15 minutes of inactivity.
---> FEAT
<--- 530 You aren't logged in
---> AUTH TLS
<--- 500 This security scheme is not implemented
---> USER missive_test
<--- 331 User missive_test OK. Password required
---> PASS XXXX
<--- 230 OK. Current directory is /              
---> FEAT
<--- 500 Unknown command
---> PWD
<--- 257 "/" is your current location
---> TYPE I
<--- 200 TYPE is now 8-bit binary
---> PORT 172,19,0,4,159,62
<--- 200 PORT command successful
---> ALLO 457
<--- 500 Unknown command
---> STOR ftptest.php
---- Accepted data connection from (172.19.0.2) port 20
<--- 150 Connecting to port 40766
---- Closing data socket
<--- 226-File successfully transferred
<--- 226 0.000 seconds (measured here), 3.16 Mbytes per second
---> SITE UTIME 20171030154823 ftptest.php
<--- 500 Unknown command
---> SITE UTIME ftptest.php 20171030154823 20171030154823 20171030154823 UTC
<--- 500 Unknown command
457 bytes transferred

OK, that was successful. Here is the passive version in LFTP, again successful.

I notice the warning at the start, about an address needing to be fixed - could that be relevant? If either side advertises itself to the other as "localhost", that might be a problem :-):

lftp missive_test@missive-testbox:/> set ftp:passive-mode on 
lftp missive_test@missive-testbox:/> put ftptest.php        
---> PASV
<--- 227 Entering Passive Mode (127,0,0,1,117,54)
---- Address returned by PASV seemed to be incorrect and has been fixed
---- Connecting data socket to (172.19.0.2) port 30006
---- Data connection established
---> STOR ftptest.php
<--- 150 Accepted data connection
---- Closing data socket
<--- 226-File successfully transferred
<--- 226 0.000 seconds (measured here), 1.79 Mbytes per second
457 bytes transferred

Can you try to add `--log` and `-v` to `lftp` and show us the log? Can you post a server-side FTP log of both the PHP and lftp sessions? Did you try to run the PHP code from command-line? Does it make any difference? — Martin Prikryl, Oct 30 '17 at 17:35
Good idea @Martin, thanks. I will clear down the FTP logs and generate a log excerpt for both cases (console passive and PHP script passive). Yes, the PHP script was run directly on the console - not run from a web server. — halfer, Oct 30 '17 at 17:45

score 2 · Accepted Answer · answered Oct 30 '17 at 17:28

2

It is hard to say which FTP operations are done here. But it might be that PHP is using PASV while lftp is using EPSV to set the passive mode.

In case of PASV the server sends both IP address and port number where it will await the connection. With EPSV the server instead only provides the port number and the target IP address is the one from the current FTP control connection. If NAT (network address translation) is involved (which is not unlikely within Docker setups) the server might see a different internal IP address as its own compared to the one which is externally visible from the FTP client, which means that the client cannot connect to the (wrong) IP address given in the response to the PASV command. With EPSV this problem does not exists since the client does not use a server provided IP address as target.

answered Oct 30 '17 at 17:28

Steffen Ullrich

114,247
10
131
172

Some good points, Steffan, for which many thanks. My Linux networking knowledge is a bit rusty, but I've found the containers are both on `172.19.0.x`, and they can reach each other. See my update. [1/2] – halfer Oct 30 '17 at 17:41
I've not heard of `EPSV`, I wasn't aware of that mode! Martin in the comments suggests I post the FTP server logs for the console PASV and PHP script PASV attempts, to see how they differ. I'd not thought of that, so I will work to gather that data next. [2/2] – halfer Oct 30 '17 at 17:43
Hmm, your train of thought prompted me to wonder whether the FTP server knows itself by another IP address. However, I have checked `ifconfig` on both containers, and they only know one "external" IP address for `eth0`, and `lo` for the loopback address. Bah, I'd hoped that was it! – halfer Oct 30 '17 at 17:48
@halfer: can you make a packet capture to see the difference between the PHP client and the lftp client and also if the correct IP address is used inside the PORT response? – Steffen Ullrich Oct 30 '17 at 17:55
Good idea. If the client/server logging doesn't do it, I will pursue that avenue. Updates to follow! – halfer Oct 30 '17 at 17:56
I've added the console client logs, and it seems that the console passive mode does some IP address fixing. I wonder if the PHP `ftp_*` funcs are just not as helpful? `:-)` – halfer Oct 30 '17 at 18:02
Fixed it! I will write it up in another answer, but your idea of IP visibility was basically it. It looks like the Docker version of PureFTPd sets the passive IP to `localhost` unless it is overridden in a child `Dockerfile`. Thanks for the pointers. – halfer Oct 30 '17 at 18:23

halfer · Answer 2 · 2017-10-30T18:38:16.800

A combination of helpful answers and comments, plus the warning from LFTP, led me to a solution. The issue is related to IP visibility in PASV mode, as Steffen surmised. The LFTP client had helpfully detected that my server was misconfigured, and so fixed it transparently, which is where the confusion arose.

It's worth noting that PHP is not that smart or kind - it does no such fixing (which is technically correct, of course).

The reason for that configuration is the default Dockerfile settings:

ENV PUBLIC_HOST localhost

So, what I have done for now, is to replace this in my own Dockerfile with the LAN IP:

ENV PUBLIC_HOST 172.19.0.2

One restart later, the fix-up message is gone from LFTP, and my PHP script works.

Update

Since I don't know if I can rely on the staticness of the above IP address, I have reset it to the name of the container:

ENV PUBLIC_HOST missive-testbox

This seems to work fine.

How to debug why PHP FTP won't work in PASV mode, when console FTP seems to work fine?

Update

Update 2

2 Answers2

Update