curl icon indicating copy to clipboard operation
curl copied to clipboard

2 seconds delay after upload a file to Microsoft FTP server

Open gold22 opened this issue 1 year ago • 1 comments

I did this

git clone https://github.com/curl/curl.git
cd curl
autoreconf -fi
./configure --disable-shared --enable-debug --enable-maintainer-mode --with-openssl
make
./src/curl -T README --verbose --silent --user ftpuser --ssl --insecure ftp://10.69.41.70
Enter host password for user 'ftpuser':
* !!! WARNING !!!
* This is a debug build of libcurl, do not use in production.
* STATE: INIT => SETUP handle 0x59b375a70c28; line 2179
* STATE: SETUP => CONNECT handle 0x59b375a70c28; line 2195
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => CONNECTING handle 0x59b375a70c28; line 2236
*   Trying 10.69.41.70:21...
* Connected to 10.69.41.70 (10.69.41.70) port 21
* STATE: CONNECTING => PROTOCONNECT handle 0x59b375a70c28; line 2339
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x59b375a70c28; line 2363
< 220 Microsoft FTP Service
> AUTH SSL
< 234 AUTH command ok. Expecting TLS Negotiation.
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [85 bytes data]
* TLSv1.2 (IN), TLS handshake, Certificate (11):
{ [1051 bytes data]
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
{ [365 bytes data]
* TLSv1.2 (IN), TLS handshake, Server finished (14):
{ [4 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
} [102 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 / secp384r1 / RSASSA-PSS
* Server certificate:
*  subject: C=CH; L=XX; O=Plesk; CN=XX; [email protected]
*  start date: Oct 14 07:13:46 2024 GMT
*  expire date: Oct 14 07:13:46 2025 GMT
*  issuer: C=CH; L=XX; O=Plesk; CN=XX; [email protected]
*  SSL certificate verify result: self-signed certificate (18), continuing anyway.
*   Certificate level 0: Public key type RSA (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
* Connected to 10.69.41.70 (10.69.41.70) port 21
} [5 bytes data]
> USER ftpuser
{ [5 bytes data]
< 331 Password required
} [5 bytes data]
> PASS ******
{ [5 bytes data]
< 230 User logged in.
} [5 bytes data]
> PBSZ 0
{ [5 bytes data]
< 200 PBSZ command successful.
} [5 bytes data]
> PROT P
{ [5 bytes data]
< 200 PROT command successful.
} [5 bytes data]
> PWD
{ [5 bytes data]
< 257 "/" is current directory.
* Entry path is '/'
* STATE: PROTOCONNECTING => DO handle 0x59b375a70c28; line 2384
* Request has same path as previous transfer
} [5 bytes data]
> EPSV
* Connect data stream passively
* STATE: DO => DOING handle 0x59b375a70c28; line 2452
{ [5 bytes data]
< 229 Entering Extended Passive Mode (|||59809|)
* Connecting to 10.69.41.70 (10.69.41.70) port 59809
* STATE: DOING => DOING_MORE handle 0x59b375a70c28; line 2534
*   Trying 10.69.41.70:59809...
* SSL reusing session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
> TYPE I
{ [5 bytes data]
< 200 Type set to I.
} [5 bytes data]
> STOR README
{ [5 bytes data]
< 125 Data connection already open; Transfer starting.
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [85 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 / secp384r1 / UNDEF
* Server certificate:
*  subject: C=CH; L=XX; O=XX; CN=XX; [email protected]
*  start date: Oct 14 07:13:46 2024 GMT
*  expire date: Oct 14 07:13:46 2025 GMT
*  issuer: C=CH; L=XX; O=XX; CN=XX; [email protected]
*  SSL certificate verify result: self-signed certificate (18), continuing anyway.
* Connected 2nd connection to 10.69.41.70 port 59809
* STATE: DOING_MORE => DID handle 0x59b375a70c28; line 2558
* STATE: DID => PERFORMING handle 0x59b375a70c28; line 2583
* sending last upload chunk of 1664 bytes
} [5 bytes data]
* Curl_xfer_send(len=1664, eos=1) -> 0, 1664
} [1664 bytes data]
* shutdown start on secondary connection
} [5 bytes data]
* TLSv1.2 (OUT), TLS alert, close notify (256):
} [2 bytes data]

>>> 2 seconds delay is here <<<

* shutdown timeout
* Shutdown send direction error: 28. Broken server? Proceeding as if everything is ok.
* upload completely sent off: 1664 bytes
* STATE: PERFORMING => DONE handle 0x59b375a70c28; line 2772
* multi_done[DONE]: status: 0 prem: 0 done: 0
* Remembering we are in dir ""
* Curl_multi_closed, fd=7 multi is 0x59b375a6f918
* Curl_multi_closed, fd=7 entry is (nil)
{ [5 bytes data]
< 226 Transfer complete.
* Connection #0 to host 10.69.41.70 left intact

I expected the following

There are no delays during a file upload.

The issue is related to the bug https://github.com/curl/curl/issues/14843.

curl/libcurl version

curl-dev

operating system

Ubuntu 24.04 x86_64

gold22 avatar Oct 15 '24 10:10 gold22

I suspect the MS FTP server is not sending its TLS close notify and instead waits for curl to close the connection, while curl is waiting 2 seconds for the TLS close notify from the server. Well, the MSFTP server does not implement TLS correctly here, but that does not help you.

@bagder: we could, on FTP uploads, signal the shutdown handling to just send the TLS close notify and close, without waiting for the server's reply. That is the only thing I can think of how curl can accommodate such a server behaviour.

icing avatar Oct 16 '24 09:10 icing

After internal discussion, we see this as a bug in the Microsoft FTP server. A workaround on the curl side would make the connection shutdown handling more complicated as it needs to be. We'd need to manage a new state in all TLS backends we use. This seems not worth it due to the complications involved.

We decided to close this issue.

icing avatar Mar 10 '25 17:03 icing