-
Notifications
You must be signed in to change notification settings - Fork 161
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Put of empty file not possible if TLS is used #420
Comments
I'm having the exact same issue. I was never able to fix it. Happens only with empty files (0 bytes in size). EDIT: Temporary workaround for the problem:
These are example values. If I understand everything correctly, that will timeout after 15 seconds of network inactivity, retry 2 times sending the file in question, interval for reconnect will be minimum of 5 seconds (multiplied by net:reconnect-interval-multiplier each next try). This however will still return with fatal error code (making any of your scripts fail). The simplest solution is to "suppress" this error e.g. like this (if using bash): |
I cannot reproduce it with lftp-4.8.3. Can you please try the latest version? |
I'm using the latest version. Error exists in passive mode transfer to proFTP server which enforces SSL connections. I've switched to SFTP where there's no such issue. If you want to I can try to get logs from the server where it is still happening. |
I used lftp 4.8.3 and ProFTPd 1.3.6 both the latest version at the time of the tests. |
I'm seeing same problem with lftp, but with a different ftp server (vspftd). The issue only happens, when lftp is compiled with openssl and 0 size file is uploaded with over SSL. It looks like, that if lftp fstat() file and finds out, that it's 0 size file, it waits for data instead of sending "EOF". How can I check, that it is this case? |
This is regression since commit:
|
Reverting offending patch fix the issue. |
the problem was the lack of ssl handshake |
Thanks. :) Also, I guess you can close the #377 |
What is happening?
When sending a file with length 0 (zero) over a TLS secured connection lftp is "hanging". I.e. lftp is waiting for a long time (maybe indefenitly) to STOR the file.
This error happend before with version 4.7.3 and 4.7.6 --> see Bug #332. The problem does not occour with lftp 4.6.0.
Participants:
lftp 4.8.3
ProFTPd 1.3.6
VL Trader 5.3.0.20 (to verify the bug)
RHEL 6.8 as the linux test system
How to reproduce the problem:
My tests showed that this only happens if the FTP server is forcing TLS on the Data Connection.
It didn't matter how "set ftp:ssl-protect-data" was set in lftp.
Any file > 0 doesn't produce this behaviour.
lftp settings:
default except
set ssl:verify-certificate no
ProFTPd TLS settings:
TLSEngine on
TLSRenegotiate none
TLSLog
TLSProtocol ALL
TLSRequired on
TLSVerifyClient on
TLSPKCS12File
TLSPassPhraseProvider
TLSCACertificateFile
TLSOptions NoSessionReuseRequired NoEmptyFragments
TLSCipherSuite AES:3DES:!aNULL:!MD5:!aDSS
Details/Logs:
-------------------------- lftp 4.8.3 log --------------------------
---- dns cache hit
---- attempt number 1 (max_retries=1000)
---- Connecting to localhost (127.0.0.1) port 2121
---> FEAT
<--- 211-Features:
<--- 211-AUTH TLS
<--- 211-CCC
<--- 211-CLNT
<--- 211-EPRT
<--- 211-EPSV
<--- 211-HOST
<--- 211-MDTM
<--- 211-MFF modify;UNIX.group;UNIX.mode;
<--- 211-MFMT
<--- 211-MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;
<--- 211-PBSZ
<--- 211-PROT
<--- 211-REST STREAM
<--- 211-SIZE
<--- 211-SSCN
<--- 211-TVFS
<--- 211 End
---> AUTH TLS
<--- 234 AUTH TLS successful
---> CLNT lftp/4.8.3
Certificate depth: 1; subject:
Certificate depth: 0; subject:
WARNING: Certificate verification: subjectAltName does not match âlocalhostâ (29:B6:C8:DA:91:B8:DC:DB:AD:31:93:FE:3E:01:CB:13:A4:7F:CD:9F)
<--- 200 OK
---> HOST localhost
<--- 504 localhost: Unknown hostname provided
---> OPTS MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner
<--- 200 MLST OPTS modify;perm;size;type;UNIX.group;UNIX.mode;
---> USER s204010
<--- 232 User s204010 logged in
---> PWD
<--- 257 "/home/s204010" is the current directory
---> PBSZ 0
<--- 200 PBSZ 0 successful
---> PROT C
<--- 534 Unwilling to accept security parameters
---> TYPE I
<--- 200 Type set to I
---> PASV
<--- 227 Entering Passive Mode (127,0,0,1,39,112).
---- Connecting data socket to (127.0.0.1) port 10096
---- Data connection established
0:0 translated to pair 0:0 (0,0)
0 translated to pair 0:0 (0,0)
0:0 translated to pair 0:0 (0,0)
0 translated to pair 0:0 (0,0)
0:0 translated to pair 0:0 (0,0)
0 translated to pair 0:0 (0,0)
---> ALLO 0
<--- 200 ALLO command successful
---> STOR empty.txt
<--- 522 SSL/TLS required on the data channel
---- Closing data socket
---> PROT P
<--- 200 Protection set to Private
---> PASV
<--- 227 Entering Passive Mode (127,0,0,1,39,102).
---- Connecting data socket to (127.0.0.1) port 10086
---- Data connection established
0:0 translated to pair 0:0 (0,0)
0 translated to pair 0:0 (0,0)
0:0 translated to pair 0:0 (0,0)
0 translated to pair 0:0 (0,0)
0:0 translated to pair 0:0 (0,0)
0 translated to pair 0:0 (0,0)
---> ALLO 0
<--- 200 ALLO command successful
---> STOR empty.txt
<--- 150 Opening BINARY mode data connection for empty.txt
Interrupt <--- ^C
---> ABOR
---- Closing aborted data socket
<--- 425 Unable to build data connection: Operation not permitted
<--- 226 Abort successful
-------------------------- lftp 4.8.3 log --------------------------
----------------------- proftpd 1.3.6 TLS log ------------------------
TLS/TLS-C requested, starting TLS handshake
client supports secure renegotiations
Client: DC =
TLSv1.2 connection accepted, using cipher ECDHE-RSA-AES256-GCM-SHA384 (256 bits)
Received user : s204010
TLS/X509 cert mapping successful for user 's204010'
PROT: TLSRequired requires protection for data transfers
PROT: unwilling to accept security parameter (C)
SSL/TLS required but absent on data channel, denying STOR command
Protection set to Private
starting TLS negotiation on data connection
unable to accept TLS connection: received EOF that violates protocol
unable to accept TLS connection: usually this indicates an FTP-aware router, NAT, or firewall interfering with the TLS handshake
unable to open data connection: TLS negotiation failed
----------------------- proftpd 1.3.6 TLS log ------------------------
------------------------ proftpd 1.3.6 log -------------------------
RELINQUISH PRIVS at main.c:1268
no matching vhost found for 127.0.0.1#2121, using 'FTP with TLS' listening on wildcard address
ROOT PRIVS at main.c:1073
SETUP PRIVS at main.c:1078
session requested from client in unknown class
performing module session initializations
mod_cap/1.1: lowering of capabilities disabled
ROOT PRIVS at mod_tls.c:5009
RELINQUISH PRIVS at mod_tls.c:5012
ROOT PRIVS at mod_tls.c:11034
RELINQUISH PRIVS at mod_tls.c:11037
ROOT PRIVS at mod_tls.c:3193
RELINQUISH PRIVS at mod_tls.c:3223
mod_tls/2.7: supporting SSLv3, TLSv1, TLSv1.1, TLSv1.2 protocols
ROOT PRIVS at mod_tls.c:5725
RELINQUISH PRIVS at mod_tls.c:5734
ROOT PRIVS at mod_tls.c:5784
RELINQUISH PRIVS at mod_tls.c:5786
ROOT PRIVS at mod_tls.c:5869
RELINQUISH PRIVS at mod_tls.c:6425
RELINQUISH PRIVS at mod_log.c:2517
mod_log: opening ExtendedLog '/var/log/proftpd/access.log'
ROOT PRIVS at mod_log.c:2564
RELINQUISH PRIVS at mod_log.c:2567
mod_log: opening ExtendedLog '/var/log/proftpd/auth.log'
ROOT PRIVS at mod_log.c:2564
RELINQUISH PRIVS at mod_log.c:2567
ROOT PRIVS at mod_auth.c:215
opening scoreboard '/var/run/proftpd/proftpd.scoreboard'
RELINQUISH PRIVS at mod_auth.c:217
connected - local : 127.0.0.1:2121
connected - remote : 127.0.0.1:39662
FTP session opened.
dispatching PRE_CMD command 'FEAT' to mod_tls
dispatching PRE_CMD command 'FEAT' to mod_core
dispatching PRE_CMD command 'FEAT' to mod_core
dispatching CMD command 'FEAT' to mod_core
dispatching LOG_CMD command 'FEAT' to mod_log
dispatching PRE_CMD command 'AUTH TLS' to mod_tls
dispatching PRE_CMD command 'AUTH TLS' to mod_core
dispatching PRE_CMD command 'AUTH TLS' to mod_core
dispatching CMD command 'AUTH TLS' to mod_tls
dispatching LOG_CMD command 'AUTH TLS' to mod_log
dispatching PRE_CMD command 'CLNT lftp/4.8.3' to mod_tls
dispatching PRE_CMD command 'CLNT lftp/4.8.3' to mod_core
dispatching PRE_CMD command 'CLNT lftp/4.8.3' to mod_core
dispatching CMD command 'CLNT lftp/4.8.3' to mod_core
dispatching LOG_CMD command 'CLNT lftp/4.8.3' to mod_log
dispatching PRE_CMD command 'HOST localhost' to mod_tls
dispatching PRE_CMD command 'HOST localhost' to mod_core
dispatching PRE_CMD command 'HOST localhost' to mod_core
dispatching CMD command 'HOST localhost' to mod_core
Unknown host 'localhost' requested on 127.0.0.1#2121, refusing HOST command
dispatching LOG_CMD_ERR command 'HOST localhost' to mod_log
dispatching PRE_CMD command 'OPTS MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_tls
dispatching PRE_CMD command 'OPTS MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_core
dispatching PRE_CMD command 'OPTS MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_core
dispatching CMD command 'OPTS MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_core
dispatching PRE_CMD command 'OPTS_MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_tls
dispatching PRE_CMD command 'OPTS_MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_core
dispatching PRE_CMD command 'OPTS_MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_core
dispatching CMD command 'OPTS_MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_facts
dispatching LOG_CMD command 'OPTS_MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_log
dispatching LOG_CMD command 'OPTS MLST modify;perm;size;type;UNIX.group;UNIX.mode;UNIX.owner' to mod_log
dispatching PRE_CMD command 'USER s204010' to mod_tls
dispatching PRE_CMD command 'USER s204010' to mod_core
dispatching PRE_CMD command 'USER s204010' to mod_core
dispatching PRE_CMD command 'USER s204010' to mod_delay
dispatching PRE_CMD command 'USER s204010' to mod_auth
dispatching CMD command 'USER s204010' to mod_auth
USER s204010: TLS/X509 cert mapping successful
USER s204010: Authenticated without password
dispatching PRE_CMD command 'PASS (hidden)' to mod_tls
dispatching PRE_CMD command 'PASS (hidden)' to mod_core
dispatching PRE_CMD command 'PASS (hidden)' to mod_core
dispatching PRE_CMD command 'PASS (hidden)' to mod_delay
dispatching PRE_CMD command 'PASS (hidden)' to mod_auth
dispatching CMD command 'PASS (hidden)' to mod_auth
retrieved UID 501 for user 's204010'
retrieved group IDs: 6024, 100
retrieved group names: ftps, users
user 's204010' authenticated by mod_tls.c
USER PRIVS 501 at mod_auth.c:1599
RELINQUISH PRIVS at mod_auth.c:1601
ROOT PRIVS at mkhome.c:316
RELINQUISH PRIVS at mkhome.c:361
Config for FTP with TLS:
Limit
AllowAll
Limit
AllowGroup
DenyAll
DefaultServer
MultilineRFC2228
CreateHome
PassivePorts
UserID
UserName
GroupID
GroupName
DisplayConnect
LoginPasswordPrompt
UseFtpUsers
RequireValidShell
TimeoutLogin
MaxLoginAttempts
PersistentPasswd
SystemLog
ExtendedLog
ExtendedLog
TransferLog
LogFormat
LogFormat
LogFormat
Umask
AllowOverwrite
HiddenStores
DeleteAbortedStores
AllowForeignAddress
DelayEngine
CapabilitiesEngine
TLSEngine
TLSRenegotiate
TLSLog
TLSProtocol
TLSRequired
TLSVerifyClient
TLSPKCS12File
TLSCACertificateFile
TLSOptions
TLSCertMappField
TLSCipherSuite
authenticated
ROOT PRIVS at mod_auth.c:1689
opening TransferLog '/var/log/proftpd/xferlog'
setting group IDs: 6024, 100
RELINQUISH PRIVS at mod_auth.c:1731
ROOT PRIVS at mod_auth.c:1780
SETUP PRIVS at mod_auth.c:1802
in dir_check_full(): path = '/home/s204010', fullpath = '/home/s204010'
dispatching POST_CMD command 'PASS (hidden)' to mod_cap
dispatching POST_CMD command 'PASS (hidden)' to mod_tls
dispatching POST_CMD command 'PASS (hidden)' to mod_delay
dispatching POST_CMD command 'PASS (hidden)' to mod_log
dispatching POST_CMD command 'PASS (hidden)' to mod_ls
dispatching POST_CMD command 'PASS (hidden)' to mod_auth
dispatching POST_CMD command 'PASS (hidden)' to mod_rlimit
dispatching POST_CMD command 'PASS (hidden)' to mod_xfer
dispatching POST_CMD command 'PASS (hidden)' to mod_core
dispatching LOG_CMD command 'PASS (hidden)' to mod_log
dispatching LOG_CMD command 'PASS (hidden)' to mod_delay
dispatching LOG_CMD command 'PASS (hidden)' to mod_auth
USER s204010: Login successful.
dispatching POST_CMD command 'USER s204010' to mod_delay
dispatching LOG_CMD command 'USER s204010' to mod_log
dispatching LOG_CMD command 'USER s204010' to mod_delay
dispatching PRE_CMD command 'PWD' to mod_tls
dispatching PRE_CMD command 'PWD' to mod_core
dispatching PRE_CMD command 'PWD' to mod_core
dispatching CMD command 'PWD' to mod_core
in dir_check_full(): path = '/home/s204010', fullpath = '/home/s204010'
dispatching LOG_CMD command 'PWD' to mod_log
dispatching PRE_CMD command 'PBSZ 0' to mod_tls
dispatching PRE_CMD command 'PBSZ 0' to mod_core
dispatching PRE_CMD command 'PBSZ 0' to mod_core
dispatching CMD command 'PBSZ 0' to mod_tls
dispatching LOG_CMD command 'PBSZ 0' to mod_log
dispatching PRE_CMD command 'PROT C' to mod_tls
dispatching PRE_CMD command 'PROT C' to mod_core
dispatching PRE_CMD command 'PROT C' to mod_core
dispatching CMD command 'PROT C' to mod_tls
in dir_check_full(): path = '/home/s204010', fullpath = '/home/s204010'
dispatching LOG_CMD_ERR command 'PROT C' to mod_log
dispatching PRE_CMD command 'TYPE I' to mod_tls
dispatching PRE_CMD command 'TYPE I' to mod_core
dispatching PRE_CMD command 'TYPE I' to mod_core
dispatching CMD command 'TYPE I' to mod_xfer
dispatching LOG_CMD command 'TYPE I' to mod_log
dispatching PRE_CMD command 'PASV' to mod_tls
dispatching PRE_CMD command 'PASV' to mod_core
dispatching PRE_CMD command 'PASV' to mod_core
dispatching CMD command 'PASV' to mod_core
in dir_check_full(): path = '/home/s204010', fullpath = '/home/s204010'
Entering Passive Mode (127,0,0,1,39,112).
dispatching LOG_CMD command 'PASV' to mod_log
dispatching PRE_CMD command 'ALLO 0' to mod_tls
dispatching PRE_CMD command 'ALLO 0' to mod_core
dispatching PRE_CMD command 'ALLO 0' to mod_core
dispatching CMD command 'ALLO 0' to mod_xfer
ALLO requested 0 KB, 2279796 KB available on '/home/s204010'
dispatching LOG_CMD command 'ALLO 0' to mod_log
dispatching PRE_CMD command 'STOR empty.txt' to mod_tls
dispatching LOG_CMD_ERR command 'STOR empty.txt' to mod_log
dispatching LOG_CMD_ERR command 'STOR empty.txt' to mod_xfer
dispatching PRE_CMD command 'PROT P' to mod_tls
dispatching PRE_CMD command 'PROT P' to mod_core
dispatching PRE_CMD command 'PROT P' to mod_core
dispatching CMD command 'PROT P' to mod_tls
in dir_check_full(): path = '/home/s204010', fullpath = '/home/s204010'
dispatching POST_CMD command 'PROT P' to mod_xfer
dispatching LOG_CMD command 'PROT P' to mod_log
dispatching PRE_CMD command 'PASV' to mod_tls
dispatching PRE_CMD command 'PASV' to mod_core
dispatching PRE_CMD command 'PASV' to mod_core
dispatching CMD command 'PASV' to mod_core
in dir_check_full(): path = '/home/s204010', fullpath = '/home/s204010'
Entering Passive Mode (127,0,0,1,39,102).
dispatching LOG_CMD command 'PASV' to mod_log
dispatching PRE_CMD command 'ALLO 0' to mod_tls
dispatching PRE_CMD command 'ALLO 0' to mod_core
dispatching PRE_CMD command 'ALLO 0' to mod_core
dispatching CMD command 'ALLO 0' to mod_xfer
ALLO requested 0 KB, 2279796 KB available on '/home/s204010'
dispatching LOG_CMD command 'ALLO 0' to mod_log
dispatching PRE_CMD command 'STOR empty.txt' to mod_tls
dispatching PRE_CMD command 'STOR empty.txt' to mod_core
dispatching PRE_CMD command 'STOR empty.txt' to mod_core
dispatching PRE_CMD command 'STOR empty.txt' to mod_xfer
in dir_check_full(): path = '/home/s204010/empty.txt', fullpath = '/home/s204010/empty.txt'
in dir_check_full(): setting umask to 0007 (was 0007)
HiddenStore: complex path, will rename /home/s204010/.in.empty.txt.31752 to /home/s204010/empty.txt
dispatching CMD command 'STOR empty.txt' to mod_xfer
UseReverseDNS off, returning IP address instead of DNS name
passive data connection opened - local : 127.0.0.1:10086
passive data connection opened - remote : 127.0.0.1:48548
removing aborted HiddenStores file '/home/s204010/.in.empty.txt.31752'
removing aborted file '/home/s204010/empty.txt'
error deleting aborted file '/home/s204010/empty.txt': No such file or directory
Transfer aborted after 0 bytes in 0.00 seconds
dispatching LOG_CMD_ERR command 'STOR empty.txt' to mod_log
dispatching LOG_CMD_ERR command 'STOR empty.txt' to mod_xfer
removing aborted HiddenStores file '/home/s204010/.in.empty.txt.31752'
dispatching PRE_CMD command 'ABOR' to mod_tls
dispatching PRE_CMD command 'ABOR' to mod_core
dispatching PRE_CMD command 'ABOR' to mod_core
dispatching CMD command 'ABOR' to mod_xfer
notice: user s204010: aborting transfer: Data connection closed
dispatching LOG_CMD command 'ABOR' to mod_log
dispatching LOG_CMD command 'ABOR' to mod_xfer
dispatching PRE_CMD command 'QUIT' to mod_tls
dispatching PRE_CMD command 'QUIT' to mod_core
dispatching PRE_CMD command 'QUIT' to mod_core
dispatching CMD command 'QUIT' to mod_core
dispatching LOG_CMD command 'QUIT' to mod_log
dispatching LOG_CMD command 'QUIT' to mod_core
FTP session closed.
------------------------ proftpd 1.3.6 log -------------------------
----------------------- proftpd 1.3.6 trace ------------------------
tls:17: calling SSL_accept() on ctrl conn fd 0
tls:17: SSL_accept() returned -1 for ctrl conn fd 0
tls:17: WANT_READ encountered while accepting ctrl conn on fd 0, waiting to read data
tls:17: calling SSL_accept() on ctrl conn fd 0
tls:5: received SNI 'localhost'
tls:17: SSL_accept() returned -1 for ctrl conn fd 0
tls:17: WANT_READ encountered while accepting ctrl conn on fd 0, waiting to read data
tls:17: calling SSL_accept() on ctrl conn fd 0
tls:17: SSL_accept() returned 1 for ctrl conn fd 0
tls:17: TLS handshake on ctrl conn fd 0 COMPLETED
tls:9: no NPN negotiated
tls:17: calling SSL_accept() on data conn fd 19
tls:17: SSL_accept() returned -1 for data conn fd 19
tls:17: WANT_READ encountered while accepting data conn on fd 19, waiting to read data
tls:17: calling SSL_accept() on data conn fd 19
tls:17: SSL_accept() returned -1 for data conn fd 19
tls:17: WANT_READ encountered while accepting data conn on fd 19, waiting to read data
tls:17: calling SSL_accept() on data conn fd 19
tls:17: SSL_accept() returned 0 for data conn fd 19
----------------------- proftpd 1.3.6 trace ------------------------
The text was updated successfully, but these errors were encountered: