Common client connection errors when using server getting started guide

[tomharvey]

Moving the commentary from #85 over here.

When I use the Getting started guide to spin up a server, the server isn't accessible from many common clients - particularly these MacOS ones.

Success cases

✅ - FTP CLI (on Ubuntu)
✅ - Firefox (72.0.2 (64-bit) on MacOS)

On Ubuntu 18.04 I've installed aioftp and am running python -m aioftp --memory --family ipv4 to start ther server.

ftp command line

The client outputs

$ ftp 172.16.11.120 2121

Connected to 172.16.11.120.
220 welcome
Name (172.16.11.120:thomasharvey): 
230 anonymous login
Remote system type is UNIX.
Using binary mode to transfer files.

and on the server I see:

aioftp v0.15.0
[17:04:06]: [aioftp.server] serving on 0.0.0.0:2121
[17:06:47]: [aioftp.server] new connection from 172.16.11.120:47164
[17:06:47]: [aioftp.server] 220 welcome
[17:06:48]: [aioftp.server] USER thomasharvey
[17:06:48]: [aioftp.server] 230 anonymous login
[17:06:48]: [aioftp.server] SYST
[17:06:48]: [aioftp.server] 215 UNIX Type: L8

Firefox

I can connect OK, the server shows:

aioftp v0.15.0
[17:15:36]: [aioftp.server] serving on 0.0.0.0:2121
[17:15:52]: [aioftp.server] new connection from 172.16.11.4:63333
[17:15:52]: [aioftp.server] 220 welcome
[17:15:52]: [aioftp.server] USER anonymous
[17:15:52]: [aioftp.server] 230 anonymous login
[17:15:52]: [aioftp.server] SYST
[17:15:52]: [aioftp.server] 215 UNIX Type: L8
[17:15:52]: [aioftp.server] FEAT
[17:15:52]: [aioftp.server] 502 'feat' not implemented
[17:15:52]: [aioftp.server] PWD
[17:15:52]: [aioftp.server] 257 "/"
[17:15:52]: [aioftp.server] TYPE I
[17:15:52]: [aioftp.server] 200 
[17:15:52]: [aioftp.server] PASV
[17:15:52]: [aioftp.server] 227-listen socket created
[17:15:52]: [aioftp.server] 227 (0,0,0,0,172,87)
[17:15:52]: [aioftp.server] CWD /
[17:15:52]: [aioftp.server] 250 
[17:15:52]: [aioftp.server] LIST
[17:15:52]: [aioftp.server] 150 list transfer started
[17:15:52]: [aioftp.server] 226 list transfer done

Failure cases

❌ - FTP CLI (on MacOS)
❌ - Transmit (on MacOS)
❌ - Cyberduck (on MacOS)
❌ - Filezilla (on MacOS)
❌ - Finder (on MacOS)

Transmit

Client log:

**********

Date/Time: 2020-03-03 17:05:57 +0000

1: Transmit 5.6.3 (x86_64) Session Transcript [Version 10.15.2 (Build 19C57)] (03/03/2020, 18:05)
1: LibNcFTP 3.2.3 (July 23, 2009) compiled for UNIX
1: 220: welcome
1: Connected to 172.16.11.120.
1: Cmd: USER anonymous
1: 230: anonymous login
1: Cmd: TYPE A
1: 200: 
1: Logged in to 172.16.11.120 as anonymous.
1: Cmd: SYST
1: 215: UNIX Type: L8
1: Cmd: FEAT
1: 502: 'feat' not implemented
1: Cmd: PWD
1: 257: "/"
1: Cmd: PASV
1: Cannot parse PASV response: listen socket created
1: 227: listen socket created
1:      (0,0,0,0,137,217)
1: Passive mode refused.
1: Connection falling back to port (PORT) mode.
1: Cmd: PORT 172,16,11,4,244,200
1: 502: 'port' not implemented
1: Cmd: PORT 172,16,11,4,244,201
1: 502: 'port' not implemented
1: Cmd: PORT 172,16,11,4,244,202
1: 502: 'port' not implemented
1: Cmd: PORT 172,16,11,4,244,203
1: 502: 'port' not implemented
1: Canceling…
1: Disconnecting from server…
1: Cmd: QUIT
1: 221: bye

And on the server side:

aioftp v0.15.0
[17:05:50]: [aioftp.server] serving on 0.0.0.0:2121
[17:05:57]: [aioftp.server] new connection from 172.16.11.4:62663
[17:05:57]: [aioftp.server] 220 welcome
[17:05:57]: [aioftp.server] USER anonymous
[17:05:57]: [aioftp.server] 230 anonymous login
[17:05:57]: [aioftp.server] TYPE A
[17:05:57]: [aioftp.server] 200 
[17:05:57]: [aioftp.server] SYST
[17:05:57]: [aioftp.server] 215 UNIX Type: L8
[17:05:57]: [aioftp.server] FEAT
[17:05:57]: [aioftp.server] 502 'feat' not implemented
[17:05:57]: [aioftp.server] PWD
[17:05:57]: [aioftp.server] 257 "/"
[17:05:57]: [aioftp.server] PASV
[17:05:57]: [aioftp.server] 227-listen socket created
[17:05:57]: [aioftp.server] 227 (0,0,0,0,137,217)
[17:05:57]: [aioftp.server] PORT 172,16,11,4,244,200
[17:05:57]: [aioftp.server] 502 'port' not implemented
[17:05:57]: [aioftp.server] PORT 172,16,11,4,244,201
[17:05:57]: [aioftp.server] 502 'port' not implemented
[17:05:57]: [aioftp.server] PORT 172,16,11,4,244,202
[17:05:57]: [aioftp.server] 502 'port' not implemented
[17:05:57]: [aioftp.server] PORT 172,16,11,4,244,203
[17:05:57]: [aioftp.server] 502 'port' not implemented
[17:05:57]: [aioftp.server] QUIT
[17:05:57]: [aioftp.server] 221 bye
[17:05:57]: [aioftp.server] closing connection from 172.16.11.4:62663

Cyberduck

Client log:

2020-03-03 18:09:58.858685+0100 PWD
2020-03-03 18:09:58.916890+0100 220 welcome
2020-03-03 18:09:58.917302+0100 USER anonymous
2020-03-03 18:09:58.921265+0100 230 anonymous login
2020-03-03 18:09:58.921354+0100 FEAT
2020-03-03 18:09:58.944287+0100 502 'feat' not implemented
2020-03-03 18:09:58.944396+0100 SYST
2020-03-03 18:09:58.949611+0100 215 UNIX Type: L8
2020-03-03 18:09:58.951729+0100 PWD
2020-03-03 18:09:58.955885+0100 257 "/"
2020-03-03 18:09:58.956282+0100 STAT /
2020-03-03 18:09:58.960571+0100 502 'stat' not implemented
2020-03-03 18:09:58.960861+0100 CWD /
2020-03-03 18:09:58.964190+0100 250
2020-03-03 18:09:58.964260+0100 TYPE A
2020-03-03 18:09:58.968861+0100 200
2020-03-03 18:09:58.968979+0100 PASV
2020-03-03 18:09:58.993767+0100 227-listen socket created
227 (0,0,0,0,139,73)
2020-03-03 18:09:58.994043+0100 CWD /
2020-03-03 18:09:58.998878+0100 250
2020-03-03 18:09:58.999037+0100 TYPE A
2020-03-03 18:09:59.002920+0100 200
2020-03-03 18:09:59.003037+0100 PASV
2020-03-03 18:09:59.007835+0100 227-listen socket already exists
227 (0,0,0,0,139,73)

And on the server side:

aioftp v0.15.0
[17:09:55]: [aioftp.server] serving on 0.0.0.0:2121
[17:09:58]: [aioftp.server] new connection from 172.16.11.4:62881
[17:09:58]: [aioftp.server] 220 welcome
[17:09:58]: [aioftp.server] USER anonymous
[17:09:58]: [aioftp.server] 230 anonymous login
[17:09:58]: [aioftp.server] FEAT
[17:09:58]: [aioftp.server] 502 'feat' not implemented
[17:09:58]: [aioftp.server] SYST
[17:09:58]: [aioftp.server] 215 UNIX Type: L8
[17:09:58]: [aioftp.server] PWD
[17:09:58]: [aioftp.server] 257 "/"
[17:09:58]: [aioftp.server] STAT /
[17:09:58]: [aioftp.server] 502 'stat' not implemented
[17:09:58]: [aioftp.server] CWD /
[17:09:58]: [aioftp.server] 250 
[17:09:58]: [aioftp.server] TYPE A
[17:09:58]: [aioftp.server] 200 
[17:09:58]: [aioftp.server] PASV
[17:09:58]: [aioftp.server] 227-listen socket created
[17:09:58]: [aioftp.server] 227 (0,0,0,0,139,73)
[17:09:58]: [aioftp.server] CWD /
[17:09:58]: [aioftp.server] 250 
[17:09:58]: [aioftp.server] TYPE A
[17:09:58]: [aioftp.server] 200 
[17:09:58]: [aioftp.server] PASV
[17:09:58]: [aioftp.server] 227-listen socket already exists
[17:09:58]: [aioftp.server] 227 (0,0,0,0,139,73)

Finder

The server log output:

aioftp v0.15.0
[17:10:50]: [aioftp.server] serving on 0.0.0.0:2121
[17:11:06]: [aioftp.server] new connection from 172.16.11.4:62907
[17:11:06]: [aioftp.server] new connection from 172.16.11.4:62908
[17:11:06]: [aioftp.server] 220 welcome
[17:11:06]: [aioftp.server] USER anonymous
[17:11:06]: [aioftp.server] 220 welcome
[17:11:06]: [aioftp.server] USER anonymous
[17:11:06]: [aioftp.server] 230 anonymous login
[17:11:06]: [aioftp.server] 230 anonymous login
[17:11:06]: [aioftp.server] SYST
[17:11:06]: [aioftp.server] SYST
[17:11:06]: [aioftp.server] 215 UNIX Type: L8
[17:11:06]: [aioftp.server] 215 UNIX Type: L8
[17:11:06]: [aioftp.server] PWD
[17:11:06]: [aioftp.server] 257 "/"
[17:11:06]: [aioftp.server] PWD
[17:11:06]: [aioftp.server] 257 "/"
[17:11:06]: [aioftp.server] TYPE I
[17:11:06]: [aioftp.server] TYPE I
[17:11:06]: [aioftp.server] 200 
[17:11:06]: [aioftp.server] 200 
[17:11:06]: [aioftp.server] CWD /
[17:11:06]: [aioftp.server] CWD /
[17:11:06]: [aioftp.server] 250 
[17:11:06]: [aioftp.server] 250 
[17:11:06]: [aioftp.server] PASV
[17:11:06]: [aioftp.server] PORT 172,16,11,4,245,189
[17:11:06]: [aioftp.server] 502 'port' not implemented
[17:11:06]: [aioftp.server] 227-listen socket created
[17:11:06]: [aioftp.server] 227 (0,0,0,0,149,49)
[17:11:06]: [aioftp.server] dispatcher caught exception
Traceback (most recent call last):
  File "/home/thomasharvey/.pyenv/versions/aioftp/lib/python3.7/site-packages/aioftp/server.py", line 913, in dispatcher
    result = task.result()
  File "/home/thomasharvey/.pyenv/versions/aioftp/lib/python3.7/site-packages/aioftp/server.py", line 498, in parse_command
    raise ConnectionResetError
ConnectionResetError
[17:11:06]: [aioftp.server] closing connection from 172.16.11.4:62907
[17:11:06]: [aioftp.server] dispatcher caught exception
Traceback (most recent call last):
  File "/home/thomasharvey/.pyenv/versions/aioftp/lib/python3.7/site-packages/aioftp/server.py", line 913, in dispatcher
    result = task.result()
  File "/home/thomasharvey/.pyenv/versions/aioftp/lib/python3.7/site-packages/aioftp/server.py", line 498, in parse_command
    raise ConnectionResetError
ConnectionResetError
[17:11:06]: [aioftp.server] closing connection from 172.16.11.4:62908

And god knows where to look for the finder logs :)

Filezilla

The client reports:

Status:         Connecting to 172.16.11.120:2121...
Status:         Connection established, waiting for welcome message...
Status:         Plain FTP is insecure. Please switch to FTP over TLS.
Status:         Server does not support non-ASCII characters.
Status:         Logged in
Status:         Retrieving directory listing...
Command:    PWD
Response:   257 "/"
Command:    TYPE I
Response:   200 
Command:    PASV
Response:   227-listen socket created
Response:   227 (0,0,0,0,136,203)
Command:    LIST
Error:          The data connection could not be established: ECONNREFUSED - Connection refused by server
Response:   150 list transfer started
Response:   425 Can't open data connection
Error:          Failed to retrieve directory listing

While the server outputs:

[17:17:54]: [aioftp.server] serving on 0.0.0.0:2121
[17:18:46]: [aioftp.server] new connection from 172.16.11.4:63445
[17:18:46]: [aioftp.server] 220 welcome
[17:18:46]: [aioftp.server] USER anonymous
[17:18:46]: [aioftp.server] 230 anonymous login
[17:18:46]: [aioftp.server] SYST
[17:18:46]: [aioftp.server] 215 UNIX Type: L8
[17:18:46]: [aioftp.server] FEAT
[17:18:46]: [aioftp.server] 502 'feat' not implemented
[17:18:46]: [aioftp.server] PWD
[17:18:46]: [aioftp.server] 257 "/"
[17:18:46]: [aioftp.server] TYPE I
[17:18:46]: [aioftp.server] 200 
[17:18:46]: [aioftp.server] PASV
[17:18:46]: [aioftp.server] 227-listen socket created
[17:18:46]: [aioftp.server] 227 (0,0,0,0,136,203)
[17:18:46]: [aioftp.server] LIST
[17:18:46]: [aioftp.server] 150 list transfer started
[17:18:47]: [aioftp.server] 425 Can't open data connection

[tomharvey]

Not sure if any windows clients have this error. Not sure what clients you use to test.

I hope to get a chance to look into this at the weekend so I thought I'd document it here. But if anything jumps out you from the logs , that will be good.

[tomharvey]

Interesting how they all seem to raise slightly different errors.

[pohmelie]

Transmit:

client:

1: Cmd: PASV
1: Cannot parse PASV response: listen socket created
1: 227: listen socket created
1:      (0,0,0,0,137,217)
1: Passive mode refused.
1: Connection falling back to port (PORT) mode.

server:

[17:05:57]: [aioftp.server] 227-listen socket created
[17:05:57]: [aioftp.server] 227 (0,0,0,0,137,217)

Unfortunately for transmit, multiline response is valid by ftp rfc's. So it is a transmit issue.

Cyberduck:

Looks like the same issue, but client tries to do same things twice (I don't know why).

Finder:

Looks like same thing, but we do not see finder logs though. Anyway it tries PORT after PASV, it a sign, that PASV is failed for client side.

Filezilla:

Probably the problem is in interpreting 0.0.0.0 address. Try out 127.0.0.1. Since server logs said: «there was not data connection for one second». And client logs said: «can't connect to provided address».

[tomharvey]

So, FileZilla will accept the connection when the server is as:

python -m aioftp --memory --family ipv4 --host 127.0.0.1

aioftp v0.15.0
[13:06:02]: [aioftp.server] serving on 127.0.0.1:2121
[13:06:15]: [aioftp.server] new connection from 127.0.0.1:49864
[13:06:15]: [aioftp.server] 220 welcome
[13:06:15]: [aioftp.server] AUTH TLS
[13:06:15]: [aioftp.server] 502 'auth' not implemented
[13:06:15]: [aioftp.server] AUTH SSL
[13:06:15]: [aioftp.server] 502 'auth' not implemented
[13:06:19]: [aioftp.server] USER anonymous
[13:06:19]: [aioftp.server] 230 anonymous login
[13:06:19]: [aioftp.server] SYST
[13:06:19]: [aioftp.server] 215 UNIX Type: L8
[13:06:19]: [aioftp.server] FEAT
[13:06:19]: [aioftp.server] 502 'feat' not implemented
[13:06:19]: [aioftp.server] PWD
[13:06:19]: [aioftp.server] 257 "/"
[13:06:19]: [aioftp.server] TYPE I
[13:06:19]: [aioftp.server] 200 
[13:06:19]: [aioftp.server] PASV
[13:06:19]: [aioftp.server] 227-listen socket created
[13:06:19]: [aioftp.server] 227 (127,0,0,1,194,204)
[13:06:19]: [aioftp.server] LIST
[13:06:19]: [aioftp.server] 150 list transfer started
[13:06:19]: [aioftp.server] 226 list transfer done

[pohmelie]

Yes, the problem with filezilla is that it looks like it does not respect 0.0.0.0 answer, which means «same address as command connection».

[tomharvey]

Wouldn't 127.0.0.1 suffer the "same address as command connection" problem - the client in the last FZ test was opening from 127.0.0.1:49864 while the server was bound to 127.0.0.1

I had a vague memory of this problem - that's why I spun up a VM on 172.16.11.120, to avoid the client and server being on the same IP. Anyway, that doesn't seem to have helped with transmit or Cyberduck (same errors when binding the server to 172.16.11.120 as I had with host=None), but my memory of that issue is very vague.

[pohmelie]

127.0.0.1 will work only on same machine. If you have virtual machines, 127.0.0.1 for them is itself, not your 127.0.0.1. It is same as for docker networking. You can bind server to your external ip address, then everyone in same network can connect and PASV will return actual ip address, not 0.0.0.0.

[pohmelie]

But, as I said before, 0.0.0.0 is legal and this is a client issue.