Reputation: 91
I'm trying to use Perl and Net::FTPSSL on an ubuntu server to upload a local file to an externally hosted webserver. The login works fine, using TLS, but it fails when trying to ls
the files on the remote server. The error is "Unexpected EOF on Command Channel [0] (0, 1) () at line…".
I get the same error if I use put
or get
to try to send/fetch a file. But if I try interactively using the normal unix FTP client, it works fine.
Any idea how I might fix it?
Update 21-May-2020 - I have updated the code and the output file providing more debug logging below
The code is very simple. Like this:
#!/usr/bin/perl
use strict;
use IO::Socket::SSL;
use Net::FTPSSL;
$IO::Socket::SSL::DEBUG = 3;
$Net::SSLeay::trace = 4;
my $file=$ARGV[0];
my $dir=$ARGV[1];
#----------------------------------------------------------------------
#1st try
if (1) {
#print "$server $username $password\n";
my $server="hubble.krystal.co.uk";
my $fields = `cat nickdata`;
chomp($fields);
my ($username, $password) = split /\t/, $fields;
my $rc;
open (STDERR, ">FTPLog.txt");
my $ftp = Net::FTPSSL->new($server,
Encryption => EXP_CRYPT,
Debug => 1,
OverrideHELP => 0,
Croak => 1);
$ftp->trapWarn();
$ftp->login($username, $password) || die "Cannot login\n";
$ftp->pwd;
$ftp->feat();
$ftp->noop();
$ftp->supported("MLSD");
$ftp->supported("NLST");
$ftp->quot("OPTS", "UTF8 ON");
$ftp->quot("TYPE", "I");
$ftp->quot("SYST");
#these fail
#$ftp->nlst();
$ftp->list();
exit;
}
The logfile now including SSL debug logging is as follows:
Net-FTPSSL Version: 0.42
IO-Socket-SSL Version: 2.068
Net-SSLeay Version: 1.84
IO-Socket-INET Version: 1.41
IO-Socket-INET6 might not be installed.
IO-Socket-IP Version: 0.39
IO Version: 1.42
Socket Version: 2.029
IPv6 support available via IO::Socket::IP (0.39) Key: (Family)
Perl: 5.026001 [5.26.1], OS: linux
***** IPv6 not yet supported in Net::FTPSSL! *****
Server (port): hubble.krystal.co.uk (21)
Keys: (OverrideHELP), (Encryption), (Debug), (Croak)
Values: (0), (E), (1), (1)
SKT <<< 220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
SKT <<< 220-You are user number 1 of 50 allowed.
SKT <<< 220-Local time is now 19:54. Server port: 21.
SKT <<< 220-This is a private system - No anonymous login
SKT <<< 220-IPv6 connections are also welcome on this server.
SKT <<< 220 You will be disconnected after 15 minutes of inactivity.
SKT >>> AUTH TLS
SKT <<< 234 AUTH TLS OK.
DEBUG: .../IO/Socket/SSL.pm:3010: new ctx 94714584143456
DEBUG: .../IO/Socket/SSL.pm:1620: start handshake
DEBUG: .../IO/Socket/SSL.pm:1177: global error: Undefined SSL object
DEBUG: .../IO/Socket/SSL.pm:787: ssl handshake not started
DEBUG: .../IO/Socket/SSL.pm:829: using SNI with hostname hubble.krystal.co.uk
DEBUG: .../IO/Socket/SSL.pm:880: set socket to non-blocking to enforce timeout=120
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:907: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:917: waiting for fd to become ready: SSL wants a read first
DEBUG: .../IO/Socket/SSL.pm:937: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:907: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:917: waiting for fd to become ready: SSL wants a read first
DEBUG: .../IO/Socket/SSL.pm:937: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:907: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:917: waiting for fd to become ready: SSL wants a read first
DEBUG: .../IO/Socket/SSL.pm:937: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:907: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:917: waiting for fd to become ready: SSL wants a read first
DEBUG: .../IO/Socket/SSL.pm:937: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> -1
DEBUG: .../IO/Socket/SSL.pm:907: ssl handshake in progress
DEBUG: .../IO/Socket/SSL.pm:917: waiting for fd to become ready: SSL wants a read first
DEBUG: .../IO/Socket/SSL.pm:937: socket ready, retrying connect
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> 1
DEBUG: .../IO/Socket/SSL.pm:952: ssl handshake done
Object HASH Details ... (SSL:arguments - E)
SSL_hostname ==> hubble.krystal.co.uk
SSL_verify_mode ==> 0
SSL_version ==> TLSv12
Timeout ==> 120
Object Net::FTPSSL Details ... (hubble.krystal.co.uk:21 - E)
_FTPSSL_arguments ==> HASH(0x562475877a30)
-- Croak ===> 1
-- Crypt ===> E
-- FixGetTs ===> 0
-- FixPutTs ===> 0
-- Host ===> hubble.krystal.co.uk
-- OverrideHELP ===> 0
-- Pret ===> 0
-- Timeout ===> 120
-- buf_size ===> 10240
-- data_prot ===> P
-- dcsc_mode ===> 1
-- debug ===> 1
-- debug_extra ===> 0
-- debug_no_help ===> 0
-- help_cmds_found ===> HASH(0x5624758b7740)
-- help_cmds_msg ===> 214 HELP Command Overridden by request.
-- help_cmds_no_syntax_available ===> 1
-- last_ftp_msg ===> 234 AUTH TLS OK.
-- myContext ===> HASH(0x5624758b7b18)
-- SSL_reuse_ctx ----> IO::Socket::SSL::SSL_Context=HASH(0x562475b19828)
-- context ++++> 94714584143456
-- ocsp_cache ++++> (undef)
-- ocsp_mode ++++> 0
-- verify_mode ++++> 0
-- mySocketOpts ===> HASH(0x562475384650)
-- PeerAddr ----> hubble.krystal.co.uk
-- PeerPort ----> 21
-- Proto ----> tcp
-- Timeout ----> 120
-- start_SSL_opts ===> HASH(0x5624758775e0)
-- SSL_hostname ----> hubble.krystal.co.uk
-- SSL_verify_mode ----> 0
-- SSL_version ----> TLSv12
-- Timeout ----> 120
-- trace ===> 0
-- type ===> A
_SSL_arguments ==> HASH(0x562475b198b8)
-- PeerAddr ===> 77.72.1.20
-- PeerPort ===> 21
-- Proto ===> tcp
-- SSL_check_crl ===> 0
-- SSL_cipher_list ===> ECDHE-ECDSA-AES128-GCM-SHA256 ECDHE-RSA-AES128-GCM-SHA256 DHE-RSA-AES128-GCM-SHA256 ECDHE-ECDSA-CHACHA20-POLY1305 ECDHE-RSA-CHACHA20-POLY1305 ECDHE-ECDSA-AES256-SHA ECDHE-RSA-AES256-SHA DHE-RSA-AES256-SHA ECDHE-ECDSA-AES128-SHA ECDHE-RSA-AES128-SHA DHE-RSA-AES128-SHA AES128-GCM-SHA256 AES256-SHA AES128-SHA DES-CBC3-SHA ECDHE-RSA-AES256-GCM-SHA384 ECDHE-ECDSA-AES256-GCM-SHA384 AES256-SHA256 DHE-DSS-AES256-SHA256 DHE-DSS-AES256-SHA DHE-DSS-AES128-SHA EDH-DSS-DES-CBC3-SHA !EXP !MEDIUM !LOW !eNULL !aNULL !RC4 !DES !MD5 !PSK !SRP
-- SSL_hostname ===> hubble.krystal.co.uk
-- SSL_server ===> 0
-- SSL_use_cert ===> 0
-- SSL_verify_mode ===> 0
-- SSL_version ===> TLSv12
_SSL_ctx ==> IO::Socket::SSL::SSL_Context=HASH(0x562475b19828)
-- context ===> 94714584143456
-- ocsp_cache ===> (undef)
-- ocsp_mode ===> 0
-- verify_mode ===> 0
_SSL_fileno ==> 3
_SSL_ioclass_upgraded ==> IO::Socket::INET
_SSL_last_err ==> ARRAY(0x562475afdca0)
[SSL wants a read first, 4]
_SSL_object ==> 94714593482576
_SSL_opened ==> 1
io_socket_domain ==> 2
io_socket_proto ==> 6
io_socket_timeout ==> 120
io_socket_type ==> 1
************************************************************
>>> USER +++++++
<<< 331 User <++++++> OK. Password required
>>> PASS *******
<<< 230 OK. Current restricted directory is /
<<+ 503 Unsupported command HELP.
>>> PWD
<<< 257 "/" is your current location
>>> FEAT
<<< 211-Extensions supported:
<<< EPRT
<<< IDLE
<<< MDTM
<<< SIZE
<<< MFMT
<<< REST STREAM
<<< MLST type*;size*;sizd*;modify*;UNIX.mode*;UNIX.uid*;UNIX.gid*;unique*;
<<< MLSD
<<< AUTH TLS
<<< PBSZ
<<< PROT
<<< UTF8
<<< TVFS
<<< ESTA
<<< PASV
<<< EPSV
<<< SPSV
<<< ESTP
<<< 211 End.
<<+ 111 Auto-adding OPTS Command!
>>> NOOP
<<< 200 Zzz...
<<+ 502 Unknown command MLSD.
<<+ 502 Unknown command NLST.
>>> OPTS UTF8 ON
<<< 200 OK, UTF-8 enabled
>>> TYPE I
<<< 200 TYPE is now 8-bit binary
>>> SYST
<<< 215 UNIX Type: L8
>>> PBSZ 0
<<< 200 PBSZ=0
>>> PROT P
<<< 200 Data protection level set to "private"
>>> PASV
<<< 227 Entering Passive Mode (77,72,1,20,213,32)
--- Host (77.72.1.20) Port (54560)
>>> LIST
<<< 150 Accepted data connection
DEBUG: .../IO/Socket/SSL.pm:1620: start handshake
DEBUG: .../IO/Socket/SSL.pm:1177: global error: Undefined SSL object
DEBUG: .../IO/Socket/SSL.pm:787: ssl handshake not started
DEBUG: .../IO/Socket/SSL.pm:829: using SNI with hostname 77.72.1.20
DEBUG: .../IO/Socket/SSL.pm:894: call Net::SSLeay::connect
DEBUG: .../IO/Socket/SSL.pm:897: done Net::SSLeay::connect -> 1
DEBUG: .../IO/Socket/SSL.pm:952: ssl handshake done
Unexpected EOF on Command Channel [0] (0, 1) ()
at ./nickFTPTest.pl line 45.
DEBUG: .../IO/Socket/SSL.pm:3059: free ctx 94714584143456 open=94714584143456
DEBUG: .../IO/Socket/SSL.pm:3070: OK free ctx 94714584143456
Update 2, 21-May-2020: I have added a copy of the FileZilla trace attaching to the same FTP server. FileZilla succeeds, but when I try to replicate the same commands using FTPSSL, it fails.
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 0
Status: Resolving address of <server>
Status: Connecting to 77.72.1.20:21...
Status: Connection established, waiting for welcome message...
Trace: CFtpControlSocket::OnReceive()
Response: 220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
Response: 220-You are user number 2 of 50 allowed.
Response: 220-Local time is now 20:09. Server port: 21.
Response: 220-This is a private system - No anonymous login
Response: 220-IPv6 connections are also welcome on this server.
Response: 220 You will be disconnected after 15 minutes of inactivity.
Trace: CFtpLogonOpData::ParseResponse() in state 1
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 2
Command: AUTH TLS
Trace: CFtpControlSocket::OnReceive()
Response: 234 AUTH TLS OK.
Trace: CFtpLogonOpData::ParseResponse() in state 2
Status: Initializing TLS...
Trace: tls_layer_impl::client_handshake()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: About to send CLIENT HELLO
Trace: TLS handshake: Sent CLIENT HELLO
Trace: tls_layer_impl::on_send()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: Received SERVER HELLO
Trace: TLS handshake: Processed SERVER HELLO
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: Received CERTIFICATE
Trace: TLS handshake: Processed CERTIFICATE
Trace: TLS handshake: Received SERVER KEY EXCHANGE
Trace: TLS handshake: Processed SERVER KEY EXCHANGE
Trace: TLS handshake: Received SERVER HELLO DONE
Trace: TLS handshake: Processed SERVER HELLO DONE
Trace: TLS handshake: About to send CLIENT KEY EXCHANGE
Trace: TLS handshake: Sent CLIENT KEY EXCHANGE
Trace: TLS handshake: About to send FINISHED
Trace: TLS handshake: Sent FINISHED
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: Received NEW SESSION TICKET
Trace: TLS handshake: Processed NEW SESSION TICKET
Trace: TLS handshake: Received FINISHED
Trace: TLS handshake: Processed FINISHED
Trace: TLS Handshake successful
Trace: Protocol: TLS1.2, Key exchange: ECDHE-SECP256R1-RSA-SHA512, Cipher: AES-256-GCM, MAC: AEAD
Trace: tls_layer_impl::verify_certificate()
Trace: Hostname does not match certificate SANs
Status: Verifying certificate...
Trace: CFtpControlSocket::SetAsyncRequestReply
Status: TLS connection established.
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 6
Command: USER <user>
Trace: CFtpControlSocket::OnReceive()
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 331 User <user> OK. Password required
Trace: CFtpLogonOpData::ParseResponse() in state 6
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 6
Command: PASS ********************
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 230 OK. Current restricted directory is /
Trace: CFtpLogonOpData::ParseResponse() in state 6
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 7
Command: SYST
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 215 UNIX Type: L8
Trace: CFtpLogonOpData::ParseResponse() in state 7
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 8
Command: FEAT
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 211-Extensions supported:
Response: EPRT
Response: IDLE
Response: MDTM
Response: SIZE
Response: MFMT
Response: REST STREAM
Response: MLST type*;size*;sizd*;modify*;UNIX.mode*;UNIX.uid*;UNIX.gid*;unique*;
Response: MLSD
Response: AUTH TLS
Response: PBSZ
Response: PROT
Response: UTF8
Response: TVFS
Response: ESTA
Response: PASV
Response: EPSV
Response: SPSV
Response: ESTP
Response: 211 End.
Trace: CFtpLogonOpData::ParseResponse() in state 8
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 10
Command: OPTS UTF8 ON
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 OK, UTF-8 enabled
Trace: CFtpLogonOpData::ParseResponse() in state 10
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 11
Command: PBSZ 0
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 PBSZ=0
Trace: CFtpLogonOpData::ParseResponse() in state 11
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 12
Command: PROT P
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 Data protection level set to "private"
Trace: CFtpLogonOpData::ParseResponse() in state 12
Status: Logged in
Trace: Measured latency of 17 ms
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpLogonOpData::Reset(0) in state 15
Trace: CFileZillaEnginePrivate::ResetOperation(0)
Trace: CControlSocket::SendNextCommand()
Trace: CFtpListOpData::Send() in state 0
Status: Retrieving directory listing...
Trace: CFtpChangeDirOpData::Send() in state 0
Trace: CFtpChangeDirOpData::Send() in state 1
Command: PWD
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 257 "/" is your current location
Trace: CFtpChangeDirOpData::ParseResponse() in state 1
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpChangeDirOpData::Reset(0) in state 1
Trace: CFtpListOpData::SubcommandResult(0) in state 1
Trace: CControlSocket::SendNextCommand()
Trace: CFtpListOpData::Send() in state 2
Trace: CFtpRawTransferOpData::Send() in state 0
Trace: CFtpRawTransferOpData::Send() in state 1
Command: TYPE I
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 TYPE is now 8-bit binary
Trace: CFtpRawTransferOpData::ParseResponse() in state 1
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 2
Command: PASV
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 227 Entering Passive Mode (77,72,1,20,207,20)
Trace: CFtpRawTransferOpData::ParseResponse() in state 2
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 4
Trace: Binding data connection source IP to control connection source IP 192.168.1.34
Trace: tls_layer_impl::client_handshake()
Trace: Trying to resume existing TLS session.
Command: MLSD
Trace: tls_layer_impl::on_send()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: About to send CLIENT HELLO
Trace: TLS handshake: Sent CLIENT HELLO
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 150 Accepted data connection
Trace: CFtpRawTransferOpData::ParseResponse() in state 4
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 5
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: Received SERVER HELLO
Trace: TLS handshake: Processed SERVER HELLO
Trace: TLS handshake: Received FINISHED
Trace: TLS handshake: Processed FINISHED
Trace: TLS handshake: About to send FINISHED
Trace: TLS handshake: Sent FINISHED
Trace: TLS Handshake successful
Trace: TLS Session resumed
Trace: Protocol: TLS1.2, Key exchange: ECDHE-SECP256R1, Cipher: AES-256-GCM, MAC: AEAD
Trace: tls_layer_impl::verify_certificate()
Trace: CTransferSocket::OnConnect
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: tls_layer_impl::on_read()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: tls_layer_impl::on_read()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: tls_layer_impl::on_read()
Trace: CTransferSocket::OnReceive(), m_transferMode=0
Trace: CTransferSocket::TransferEnd(1)
Trace: tls_layer_impl::shutdown()
Trace: tls_layer_impl::continue_shutdown()
Trace: CFtpControlSocket::TransferEnd()
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 226-Options: -a -l
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 226 46 matches total
Trace: CFtpRawTransferOpData::ParseResponse() in state 7
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpRawTransferOpData::Reset(0) in state 7
Trace: CFtpListOpData::SubcommandResult(0) in state 3
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpListOpData::Reset(0) in state 3
Status: Directory listing of "/" successful
Trace: CFileZillaEnginePrivate::ResetOperation(0)
Upvotes: 1
Views: 1200
Reputation: 123320
Thanks to SSL debugging one can now better see what's going on. This is from the initial FTP control connection:
DEBUG: .../IO/Socket/SSL.pm:829: using SNI with hostname hubble.krystal.co.uk
But this is from the data connection:
DEBUG: .../IO/Socket/SSL.pm:829: using SNI with hostname 77.72.1.20
This looks like two bugs for me in Net::FTPSSL which also seem to be in the current version 0.42: it should never use an IP address for SNI (which Net::FTPSSL explicitly does, IO::Socket::SSL by its own would not) and it should use the same SNI in control and data connection (i.e. the hostname in both).
Given that I have no access to the site (no anonymous login) I don't know if this is really the cause of the problem. But Net::FTP does not have this problem so it would be worth a more closer look (i.e. with SSL debugging enabled too if it does not work).
Upvotes: 1
Reputation: 91
My approach so far, which is more avoiding the problem rather than solving it, has been to install lftp
and pipe commands into lftp
. This achieves my immediate aim of doing an upload using FTP over TLS.
Upvotes: 0