curl_easy_perform() in curl 8.9.1 fails with OPERATION_TIMEOUT

[rmja]

I did this

I am uploading a file to a Microsoft FTP Service using libcurl from C#. This has worked fine, but after updating to libcurl 8.9.1 it seems as if curl_easy_perform() now returns OPERATION_TIMEOUT. The call is going through a socks proxy (needed for me to access the FTP server due to firewall restrictions).

I hope that you can use my description below, even though it is from C#. It is the the verbose output obtained through the CURLoption.DEBUGFUNCTION handler.
Note that the file is actually uploaded - but, if I specify a POSTQUOTE to be run after the upload, then it is not executed.

CURLINFO_TEXT: 09.56.39.337 Trying 52.29.67.170:1080...
CURLINFO_TEXT: 09.56.39.363 Connected to 52.29.67.170 (52.29.67.170) port 1080
CURLINFO_TEXT: 09.56.39.454 Host kamanaftps01.westeurope.cloudapp.azure.com:21 was resolved.
CURLINFO_TEXT: 09.56.39.457 IPv6: (none)
CURLINFO_TEXT: 09.56.39.459 IPv4: 52.174.49.89
CURLINFO_TEXT: 09.56.39.461 SOCKS5 connect to 52.174.49.89:21 (locally resolved)
CURLINFO_TEXT: 09.56.39.495 SOCKS5 request granted.
CURLINFO_TEXT: 09.56.39.497 Connected to 52.29.67.170 (52.29.67.170) port 1080
CURLINFO_HEADER_IN: 09.56.39.504 220 Microsoft FTP Service
CURLINFO_HEADER_OUT: 09.56.39.506 AUTH SSL
CURLINFO_HEADER_IN: 09.56.39.537 234 AUTH command ok. Expecting TLS Negotiation.
CURLINFO_TEXT: 09.56.39.540 TLSv1.2 (OUT), TLS handshake, Client hello (1):
CURLINFO_SSL_DATA_OUT: 09.56.39.542 �CURLINFO_TEXT: 09.56.39.573 TLSv1.2 (IN), TLS handshake, Server hello (2):
CURLINFO_SSL_DATA_IN: 09.56.39.575 �CURLINFO_TEXT: 09.56.39.577 TLSv1.2 (IN), TLS handshake, Certificate (11):
CURLINFO_SSL_DATA_IN: 09.56.39.579 �CURLINFO_TEXT: 09.56.39.581 TLSv1.2 (IN), TLS handshake, Server key exchange (12):
CURLINFO_SSL_DATA_IN: 09.56.39.583 CURLINFO_TEXT: 09.56.39.585 TLSv1.2 (IN), TLS handshake, Server finished (14):
CURLINFO_SSL_DATA_IN: 09.56.39.586 �CURLINFO_TEXT: 09.56.39.588 TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
CURLINFO_SSL_DATA_OUT: 09.56.39.589 �CURLINFO_TEXT: 09.56.39.591 TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_OUT: 09.56.39.592 �
CURLINFO_TEXT: 09.56.39.594 TLSv1.2 (OUT), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_OUT: 09.56.39.596 �CURLINFO_TEXT: 09.56.39.629 TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_IN: 09.56.39.631 �
CURLINFO_TEXT: 09.56.39.633 TLSv1.2 (IN), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_IN: 09.56.39.635 �CURLINFO_TEXT: 09.56.39.636 SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 / [blank] / UNDEF
CURLINFO_TEXT: 09.56.39.638 Server certificate:
CURLINFO_TEXT: 09.56.39.639 subject: CN=kamanaftps01.westeurope.cloudapp.azure.com
CURLINFO_TEXT: 09.56.39.641 start date: Sep 12 05:59:33 2023 GMT
CURLINFO_TEXT: 09.56.39.642 expire date: Oct 13 05:59:33 2024 GMT
CURLINFO_TEXT: 09.56.39.644 subjectAltName: host "kamanaftps01.westeurope.cloudapp.azure.com" matched cert's "kamanaftps01.westeurope.cloudapp.azure.com"
CURLINFO_TEXT: 09.56.39.646 issuer: C=US; ST=Arizona; L=Scottsdale; O=GoDaddy.com, Inc.; OU=http://certs.godaddy.com/repository/; CN=Go Daddy Secure Certificate Authority - G2
CURLINFO_TEXT: 09.56.39.647 SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
CURLINFO_TEXT: 09.56.39.649 Certificate level 0: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_TEXT: 09.56.39.651 Certificate level 1: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_HEADER_OUT: 09.56.39.653 USER username
CURLINFO_HEADER_IN: 09.56.39.685 331 Password required
CURLINFO_HEADER_OUT: 09.56.39.687 PASS password
CURLINFO_HEADER_IN: 09.56.39.734 230 User logged in.
CURLINFO_HEADER_OUT: 09.56.39.736 PBSZ 0
CURLINFO_HEADER_IN: 09.56.39.768 200 PBSZ command successful.
CURLINFO_HEADER_OUT: 09.56.39.770 PROT P
CURLINFO_HEADER_IN: 09.56.39.802 200 PROT command successful.
CURLINFO_HEADER_OUT: 09.56.39.805 PWD
CURLINFO_HEADER_IN: 09.56.39.837 257 "/" is current directory.
CURLINFO_TEXT: 09.56.39.840 Entry path is '/'
CURLINFO_TEXT: 09.56.39.842 Request has same path as previous transfer
CURLINFO_HEADER_OUT: 09.56.39.844 EPSV
CURLINFO_TEXT: 09.56.39.846 Connect data stream passively
CURLINFO_HEADER_IN: 09.56.39.876 229 Entering Extended Passive Mode (|||16897|)
CURLINFO_TEXT: 09.56.39.878 Hostname 52.29.67.170 was found in DNS cache
CURLINFO_TEXT: 09.56.39.880 Connecting to kamanaftps01.westeurope.cloudapp.azure.com (52.29.67.170) port 1080
CURLINFO_TEXT: 09.56.39.882 Trying 52.29.67.170:1080...
CURLINFO_TEXT: 09.56.39.907 Connected 2nd connection to 52.29.67.170 port 1080
CURLINFO_TEXT: 09.56.39.968 Host kamanaftps01.westeurope.cloudapp.azure.com:16897 was resolved.
CURLINFO_TEXT: 09.56.39.970 IPv6: (none)
CURLINFO_TEXT: 09.56.39.972 IPv4: 52.174.49.89
CURLINFO_TEXT: 09.56.39.974 SOCKS5 connect to 52.174.49.89:16897 (locally resolved)
CURLINFO_TEXT: 09.56.40.007 SOCKS5 request granted.
CURLINFO_TEXT: 09.56.40.010 Connected 2nd connection to 52.29.67.170 port 1080
CURLINFO_TEXT: 09.56.40.012 SSL reusing session ID
CURLINFO_TEXT: 09.56.40.015 TLSv1.2 (OUT), TLS handshake, Client hello (1):
CURLINFO_SSL_DATA_OUT: 09.56.40.017 �CURLINFO_HEADER_OUT: 09.56.40.019 TYPE I
CURLINFO_HEADER_IN: 09.56.40.050 200 Type set to I.
CURLINFO_HEADER_OUT: 09.56.40.053 STOR upload-testfile-5e047ec0-0bc6-4eab-854d-9c5a70f2ae61.txt.tmp
CURLINFO_HEADER_IN: 09.56.40.125 125 Data connection already open; Transfer starting.
CURLINFO_TEXT: 09.56.40.128 TLSv1.2 (IN), TLS handshake, Server hello (2):
CURLINFO_SSL_DATA_IN: 09.56.40.130 �CURLINFO_TEXT: 09.56.40.132 TLSv1.2 (IN), TLS handshake, Certificate (11):
CURLINFO_SSL_DATA_IN: 09.56.40.134 �CURLINFO_TEXT: 09.56.40.136 TLSv1.2 (IN), TLS handshake, Server key exchange (12):
CURLINFO_SSL_DATA_IN: 09.56.40.138 CURLINFO_TEXT: 09.56.40.140 TLSv1.2 (IN), TLS handshake, Server finished (14):
CURLINFO_SSL_DATA_IN: 09.56.40.142 �CURLINFO_TEXT: 09.56.40.145 TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
CURLINFO_SSL_DATA_OUT: 09.56.40.146 �CURLINFO_TEXT: 09.56.40.149 TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_OUT: 09.56.40.150 �
CURLINFO_TEXT: 09.56.40.153 TLSv1.2 (OUT), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_OUT: 09.56.40.154 �CURLINFO_TEXT: 09.56.40.188 TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_IN: 09.56.40.190 �
CURLINFO_TEXT: 09.56.40.192 TLSv1.2 (IN), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_IN: 09.56.40.194 �CURLINFO_TEXT: 09.56.40.196 SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 / [blank] / UNDEF
CURLINFO_TEXT: 09.56.40.198 Server certificate:
CURLINFO_TEXT: 09.56.40.200 subject: CN=kamanaftps01.westeurope.cloudapp.azure.com
CURLINFO_TEXT: 09.56.40.202 start date: Sep 12 05:59:33 2023 GMT
CURLINFO_TEXT: 09.56.40.204 expire date: Oct 13 05:59:33 2024 GMT
CURLINFO_TEXT: 09.56.40.206 subjectAltName: host "kamanaftps01.westeurope.cloudapp.azure.com" matched cert's "kamanaftps01.westeurope.cloudapp.azure.com"
CURLINFO_TEXT: 09.56.40.208 issuer: C=US; ST=Arizona; L=Scottsdale; O=GoDaddy.com, Inc.; OU=http://certs.godaddy.com/repository/; CN=Go Daddy Secure Certificate Authority - G2
CURLINFO_TEXT: 09.56.40.210 SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
CURLINFO_TEXT: 09.56.40.212 Certificate level 0: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_TEXT: 09.56.40.214 Certificate level 1: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_DATA_OUT: 09.56.40.217 This is a testfile
CURLINFO_TEXT: 09.56.40.219 TLSv1.2 (OUT), TLS alert, close notify (256):
CURLINFO_SSL_DATA_OUT: 09.56.40.221 �CURLINFO_TEXT: 09.56.42.234 SSL shutdown timeout
CURLINFO_TEXT: 09.56.42.236 closing connection #0

Let me know if there is some CURLOption that I can specify to help with diagnosing the issue further.
I can do the same uploads to a vsftpd server without any issues.
I believe this is related to #13904.

I expected the following

I expect the perform operation to not return an error, and if a POSTQUOTE is specified, to have it be executed.

curl/libcurl version

libcurl 8.9.1 (this worked in libcurl 8.8.0)

operating system

I have tried both on Windows and alpine linux with verified libcurl 8.9.1

[icing]

Thanks for your report. Indeed, this looks like an effect of the shutdown changes. What seems to happen:

• curl opens the FTP data connection
• uploads the file
• shuts down the data connection, a TIMEOUT error is reported (although the log times show that there seems an issue here)
• the transfer fails and your POSTQUOTE is not executed

I'll try to find the cause of the untimely TIMEOUT. Can you build a libcurl yourself for testing?

[rmja]

I may be able to, but have not done it before. I am on Windows. If you can create a libcurl-x64.dll that I can test, that would be greatly appreciated.

[icing]

I made #14848 with a possible fix for your situation. What could be interesting is to see a trace when you add curl_global_trace("ftp,ssl,tcp") at the start of your application. Then we'll see more details.

So far, I can only assume that the server is broken insofar as it does not shutdown the DATA connection properly. You notice the 2 second delay until the timeout on shutdown is reported. That is curl's default waiting time.

Note: since we have a release tomorrow, we'll not merge the PR right away and you will not get it in our daily curl Windows builds.

[rmja]

@icing thank you for looking into this! Please see the attached extended log output:

CURLINFO_TEXT: 14.32.44.840 [FTP] [STOP] setup connection -> 0
CURLINFO_TEXT: 14.32.44.847 Trying 52.29.67.170:1080...
CURLINFO_TEXT: 14.32.44.850 [TCP] cf_socket_open() -> 0, fd=1560
CURLINFO_TEXT: 14.32.44.853 [TCP] local address 0.0.0.0 port 56757...
CURLINFO_TEXT: 14.32.44.856 [TCP] adjust_pollset, !connected, POLLOUT fd=1560
CURLINFO_TEXT: 14.32.44.876 [TCP] adjust_pollset, !connected, POLLOUT fd=1560
CURLINFO_TEXT: 14.32.44.878 [TCP] connected
CURLINFO_TEXT: 14.32.44.881 Connected to 52.29.67.170 (52.29.67.170) port 1080
CURLINFO_TEXT: 14.32.44.884 [TCP] send(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.44.887 [TCP] recv(len=2) -> -1, err=81
CURLINFO_TEXT: 14.32.44.906 [TCP] recv(len=2) -> 2, err=0
CURLINFO_TEXT: 14.32.44.910 [TCP] send(len=43) -> 43, err=0
CURLINFO_TEXT: 14.32.44.912 [TCP] recv(len=2) -> -1, err=81
CURLINFO_TEXT: 14.32.44.941 [TCP] recv(len=2) -> 2, err=0
CURLINFO_TEXT: 14.32.44.999 Host kamanaftps01.westeurope.cloudapp.azure.com:21 was resolved.
CURLINFO_TEXT: 14.32.45.002 IPv6: (none)
CURLINFO_TEXT: 14.32.45.004 IPv4: 52.174.49.89
CURLINFO_TEXT: 14.32.45.007 SOCKS5 connect to 52.174.49.89:21 (locally resolved)
CURLINFO_TEXT: 14.32.45.010 [TCP] send(len=10) -> 10, err=0
CURLINFO_TEXT: 14.32.45.012 [TCP] recv(len=10) -> -1, err=81
CURLINFO_TEXT: 14.32.45.041 [TCP] recv(len=10) -> 10, err=0
CURLINFO_TEXT: 14.32.45.044 SOCKS5 request granted.
CURLINFO_TEXT: 14.32.45.048 Connected to 52.29.67.170 (52.29.67.170) port 1080
CURLINFO_TEXT: 14.32.45.052 [FTP] [STOP] -> [WAIT220]
CURLINFO_TEXT: 14.32.45.055 [TCP] recv(len=900) -> 27, err=0
CURLINFO_HEADER_IN: 14.32.45.058 220 Microsoft FTP Service
CURLINFO_TEXT: 14.32.45.062 [TCP] send(len=10) -> 10, err=0
CURLINFO_HEADER_OUT: 14.32.45.065 AUTH SSL
CURLINFO_TEXT: 14.32.45.069 [FTP] [WAIT220] -> [AUTH]
CURLINFO_TEXT: 14.32.45.092 [TCP] recv(len=900) -> 49, err=0
CURLINFO_HEADER_IN: 14.32.45.097 234 AUTH command ok. Expecting TLS Negotiation.
CURLINFO_TEXT: 14.32.45.102 [SSL] added
CURLINFO_TEXT: 14.32.45.106 [SSL] cf_connect()
CURLINFO_TEXT: 14.32.45.113 [TCP] send(len=235) -> 235, err=0
CURLINFO_TEXT: 14.32.45.117 [SSL] ossl_bio_cf_out_write(len=235) -> 235, err=0
CURLINFO_TEXT: 14.32.45.121 TLSv1.2 (OUT), TLS handshake, Client hello (1):
CURLINFO_SSL_DATA_OUT: 14.32.45.125 �CURLINFO_TEXT: 14.32.45.129 [TCP] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.133 [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.137 [SSL] populate_x509_store, path=none, blob=0
CURLINFO_TEXT: 14.32.45.144 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.147 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.152 [TCP] recv(len=3359) -> 3359, err=0
CURLINFO_TEXT: 14.32.45.155 [SSL] ossl_bio_cf_in_read(len=3359) -> 3359, err=0
CURLINFO_TEXT: 14.32.45.159 TLSv1.2 (IN), TLS handshake, Server hello (2):
CURLINFO_SSL_DATA_IN: 14.32.45.162 �CURLINFO_TEXT: 14.32.45.167 TLSv1.2 (IN), TLS handshake, Certificate (11):
CURLINFO_SSL_DATA_IN: 14.32.45.170 �CURLINFO_TEXT: 14.32.45.181 TLSv1.2 (IN), TLS handshake, Server key exchange (12):
CURLINFO_SSL_DATA_IN: 14.32.45.184 CURLINFO_TEXT: 14.32.45.189 TLSv1.2 (IN), TLS handshake, Server finished (14):
CURLINFO_SSL_DATA_IN: 14.32.45.192 �CURLINFO_TEXT: 14.32.45.196 TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
CURLINFO_SSL_DATA_OUT: 14.32.45.201 �CURLINFO_TEXT: 14.32.45.204 TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_OUT: 14.32.45.208 �
CURLINFO_TEXT: 14.32.45.212 TLSv1.2 (OUT), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_OUT: 14.32.45.216 �CURLINFO_TEXT: 14.32.45.220 [TCP] send(len=93) -> 93, err=0
CURLINFO_TEXT: 14.32.45.224 [SSL] ossl_bio_cf_out_write(len=93) -> 93, err=0
CURLINFO_TEXT: 14.32.45.229 [TCP] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.232 [SSL] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.251 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.255 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.259 [TCP] recv(len=1) -> 1, err=0
CURLINFO_TEXT: 14.32.45.263 [SSL] ossl_bio_cf_in_read(len=1) -> 1, err=0
CURLINFO_TEXT: 14.32.45.268 TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_IN: 14.32.45.272 �
CURLINFO_TEXT: 14.32.45.276 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.281 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.286 [TCP] recv(len=40) -> 40, err=0
CURLINFO_TEXT: 14.32.45.290 [SSL] ossl_bio_cf_in_read(len=40) -> 40, err=0
CURLINFO_TEXT: 14.32.45.294 TLSv1.2 (IN), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_IN: 14.32.45.299 �CURLINFO_TEXT: 14.32.45.304 [SSL] Added Session ID to cache for ftp://kamanaftps01.westeurope.cloudapp.azure.com:21 [server]
CURLINFO_TEXT: 14.32.45.308 SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 / [blank] / UNDEF
CURLINFO_TEXT: 14.32.45.312 Server certificate:
CURLINFO_TEXT: 14.32.45.316 subject: CN=kamanaftps01.westeurope.cloudapp.azure.com
CURLINFO_TEXT: 14.32.45.321 start date: Sep 12 05:59:33 2023 GMT
CURLINFO_TEXT: 14.32.45.325 expire date: Oct 13 05:59:33 2024 GMT
CURLINFO_TEXT: 14.32.45.329 subjectAltName: host "kamanaftps01.westeurope.cloudapp.azure.com" matched cert's "kamanaftps01.westeurope.cloudapp.azure.com"
CURLINFO_TEXT: 14.32.45.333 issuer: C=US; ST=Arizona; L=Scottsdale; O=GoDaddy.com, Inc.; OU=http://certs.godaddy.com/repository/; CN=Go Daddy Secure Certificate Authority - G2
CURLINFO_TEXT: 14.32.45.337 SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
CURLINFO_TEXT: 14.32.45.340 Certificate level 0: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_TEXT: 14.32.45.343 Certificate level 1: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_TEXT: 14.32.45.346 [SSL] cf_connect() -> 0, done=1
CURLINFO_TEXT: 14.32.45.349 [TCP] send(len=48) -> 48, err=0
CURLINFO_TEXT: 14.32.45.353 [SSL] ossl_bio_cf_out_write(len=48) -> 48, err=0
CURLINFO_HEADER_OUT: 14.32.45.357 USER username
CURLINFO_TEXT: 14.32.45.361 [FTP] [AUTH] -> [USER]
CURLINFO_TEXT: 14.32.45.379 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.383 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.388 [TCP] recv(len=47) -> 47, err=0
CURLINFO_TEXT: 14.32.45.391 [SSL] ossl_bio_cf_in_read(len=47) -> 47, err=0
CURLINFO_TEXT: 14.32.45.395 [SSL] cf_recv(len=900) -> 23, 0
CURLINFO_HEADER_IN: 14.32.45.398 331 Password required
CURLINFO_TEXT: 14.32.45.401 [TCP] send(len=47) -> 47, err=0
CURLINFO_TEXT: 14.32.45.404 [SSL] ossl_bio_cf_out_write(len=47) -> 47, err=0
CURLINFO_HEADER_OUT: 14.32.45.407 PASS password
CURLINFO_TEXT: 14.32.45.411 [FTP] [USER] -> [PASS]
CURLINFO_TEXT: 14.32.45.442 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.445 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.449 [TCP] recv(len=45) -> 45, err=0
CURLINFO_TEXT: 14.32.45.452 [SSL] ossl_bio_cf_in_read(len=45) -> 45, err=0
CURLINFO_TEXT: 14.32.45.455 [SSL] cf_recv(len=900) -> 21, 0
CURLINFO_HEADER_IN: 14.32.45.459 230 User logged in.
CURLINFO_TEXT: 14.32.45.463 [TCP] send(len=37) -> 37, err=0
CURLINFO_TEXT: 14.32.45.466 [SSL] ossl_bio_cf_out_write(len=37) -> 37, err=0
CURLINFO_HEADER_OUT: 14.32.45.470 PBSZ 0
CURLINFO_TEXT: 14.32.45.473 [FTP] [PASS] -> [PBSZ]
CURLINFO_TEXT: 14.32.45.493 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.497 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.502 [TCP] recv(len=54) -> 54, err=0
CURLINFO_TEXT: 14.32.45.506 [SSL] ossl_bio_cf_in_read(len=54) -> 54, err=0
CURLINFO_TEXT: 14.32.45.510 [SSL] cf_recv(len=900) -> 30, 0
CURLINFO_HEADER_IN: 14.32.45.514 200 PBSZ command successful.
CURLINFO_TEXT: 14.32.45.518 [TCP] send(len=37) -> 37, err=0
CURLINFO_TEXT: 14.32.45.522 [SSL] ossl_bio_cf_out_write(len=37) -> 37, err=0
CURLINFO_HEADER_OUT: 14.32.45.526 PROT P
CURLINFO_TEXT: 14.32.45.530 [FTP] [PBSZ] -> [PROT]
CURLINFO_TEXT: 14.32.45.548 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.551 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.555 [TCP] recv(len=54) -> 54, err=0
CURLINFO_TEXT: 14.32.45.559 [SSL] ossl_bio_cf_in_read(len=54) -> 54, err=0
CURLINFO_TEXT: 14.32.45.563 [SSL] cf_recv(len=900) -> 30, 0
CURLINFO_HEADER_IN: 14.32.45.567 200 PROT command successful.
CURLINFO_TEXT: 14.32.45.570 [TCP] send(len=34) -> 34, err=0
CURLINFO_TEXT: 14.32.45.574 [SSL] ossl_bio_cf_out_write(len=34) -> 34, err=0
CURLINFO_HEADER_OUT: 14.32.45.577 PWD
CURLINFO_TEXT: 14.32.45.581 [FTP] [PROT] -> [PWD]
CURLINFO_TEXT: 14.32.45.601 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.604 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.608 [TCP] recv(len=55) -> 55, err=0
CURLINFO_TEXT: 14.32.45.611 [SSL] ossl_bio_cf_in_read(len=55) -> 55, err=0
CURLINFO_TEXT: 14.32.45.614 [SSL] cf_recv(len=900) -> 31, 0
CURLINFO_HEADER_IN: 14.32.45.617 257 "/" is current directory.
CURLINFO_TEXT: 14.32.45.620 Entry path is '/'
CURLINFO_TEXT: 14.32.45.623 [FTP] [PWD] -> [STOP]
CURLINFO_TEXT: 14.32.45.626 [FTP] [STOP] protocol connect phase DONE
CURLINFO_TEXT: 14.32.45.629 Request has same path as previous transfer
CURLINFO_TEXT: 14.32.45.631 [FTP] [STOP] DO phase starts
CURLINFO_TEXT: 14.32.45.634 [TCP] send(len=35) -> 35, err=0
CURLINFO_TEXT: 14.32.45.637 [SSL] ossl_bio_cf_out_write(len=35) -> 35, err=0
CURLINFO_HEADER_OUT: 14.32.45.640 EPSV
CURLINFO_TEXT: 14.32.45.643 [FTP] [STOP] -> [PASV]
CURLINFO_TEXT: 14.32.45.645 Connect data stream passively
CURLINFO_TEXT: 14.32.45.648 [FTP] [PASV] perform, awaiting DATA connect
CURLINFO_TEXT: 14.32.45.665 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.668 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.671 [TCP] recv(len=72) -> 72, err=0
CURLINFO_TEXT: 14.32.45.674 [SSL] ossl_bio_cf_in_read(len=72) -> 72, err=0
CURLINFO_TEXT: 14.32.45.678 [SSL] cf_recv(len=900) -> 48, 0
CURLINFO_HEADER_IN: 14.32.45.682 229 Entering Extended Passive Mode (|||19954|)
CURLINFO_TEXT: 14.32.45.685 Hostname 52.29.67.170 was found in DNS cache
CURLINFO_TEXT: 14.32.45.688 Connecting to kamanaftps01.westeurope.cloudapp.azure.com (52.29.67.170) port 1080
CURLINFO_TEXT: 14.32.45.692 [FTP] [PASV] -> [STOP]
CURLINFO_TEXT: 14.32.45.695 [FTP] [STOP] DO phase is complete2
CURLINFO_TEXT: 14.32.45.699 Trying 52.29.67.170:1080...
CURLINFO_TEXT: 14.32.45.703 [TCP-1] cf_socket_open() -> 0, fd=1540
CURLINFO_TEXT: 14.32.45.706 [TCP-1] local address 0.0.0.0 port 56761...
CURLINFO_TEXT: 14.32.45.710 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.713 [TCP-1] adjust_pollset, !connected, POLLOUT fd=1540
CURLINFO_TEXT: 14.32.45.729 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.732 [TCP-1] adjust_pollset, !connected, POLLOUT fd=1540
CURLINFO_TEXT: 14.32.45.736 [TCP-1] connected
CURLINFO_TEXT: 14.32.45.739 Connected 2nd connection to 52.29.67.170 port 1080
CURLINFO_TEXT: 14.32.45.742 [TCP-1] send(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.745 [TCP-1] recv(len=2) -> -1, err=81
CURLINFO_TEXT: 14.32.45.749 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.765 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.768 [TCP-1] recv(len=2) -> 2, err=0
CURLINFO_TEXT: 14.32.45.771 [TCP-1] send(len=43) -> 43, err=0
CURLINFO_TEXT: 14.32.45.773 [TCP-1] recv(len=2) -> -1, err=81
CURLINFO_TEXT: 14.32.45.776 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.801 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.805 [TCP-1] recv(len=2) -> 2, err=0
CURLINFO_TEXT: 14.32.45.810 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.813 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.818 Host kamanaftps01.westeurope.cloudapp.azure.com:19954 was resolved.
CURLINFO_TEXT: 14.32.45.821 IPv6: (none)
CURLINFO_TEXT: 14.32.45.824 IPv4: 52.174.49.89
CURLINFO_TEXT: 14.32.45.827 SOCKS5 connect to 52.174.49.89:19954 (locally resolved)
CURLINFO_TEXT: 14.32.45.830 [TCP-1] send(len=10) -> 10, err=0
CURLINFO_TEXT: 14.32.45.832 [TCP-1] recv(len=10) -> -1, err=81
CURLINFO_TEXT: 14.32.45.835 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.861 [FTP] [STOP] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.865 [TCP-1] recv(len=10) -> 10, err=0
CURLINFO_TEXT: 14.32.45.869 SOCKS5 request granted.
CURLINFO_TEXT: 14.32.45.872 Connected 2nd connection to 52.29.67.170 port 1080
CURLINFO_TEXT: 14.32.45.876 [SSL-1] cf_connect()
CURLINFO_TEXT: 14.32.45.879 SSL reusing session ID
CURLINFO_TEXT: 14.32.45.883 [TCP-1] send(len=267) -> 267, err=0
CURLINFO_TEXT: 14.32.45.886 [SSL-1] ossl_bio_cf_out_write(len=267) -> 267, err=0
CURLINFO_TEXT: 14.32.45.890 TLSv1.2 (OUT), TLS handshake, Client hello (1):
CURLINFO_SSL_DATA_OUT: 14.32.45.893 �CURLINFO_TEXT: 14.32.45.897 [TCP-1] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.900 [SSL-1] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.904 [SSL-1] populate_x509_store, path=none, blob=0
CURLINFO_TEXT: 14.32.45.908 [SSL-1] cf_connect() -> 0, done=0
CURLINFO_TEXT: 14.32.45.911 [TCP] send(len=37) -> 37, err=0
CURLINFO_TEXT: 14.32.45.915 [SSL] ossl_bio_cf_out_write(len=37) -> 37, err=0
CURLINFO_HEADER_OUT: 14.32.45.918 TYPE I
CURLINFO_TEXT: 14.32.45.922 [FTP] [STOP] -> [STOR_TYPE]
CURLINFO_TEXT: 14.32.45.925 [FTP] [STOR_TYPE] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.928 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.45.941 [FTP] [STOR_TYPE] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.945 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.45.949 [SSL-1] cf_connect()
CURLINFO_TEXT: 14.32.45.952 [TCP-1] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.956 [SSL-1] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.45.959 [SSL-1] cf_connect() -> 0, done=0
CURLINFO_TEXT: 14.32.45.962 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.965 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.45.969 [TCP] recv(len=44) -> 44, err=0
CURLINFO_TEXT: 14.32.45.972 [SSL] ossl_bio_cf_in_read(len=44) -> 44, err=0
CURLINFO_TEXT: 14.32.45.976 [SSL] cf_recv(len=900) -> 20, 0
CURLINFO_HEADER_IN: 14.32.45.979 200 Type set to I.
CURLINFO_TEXT: 14.32.45.982 [TCP] send(len=96) -> 96, err=0
CURLINFO_TEXT: 14.32.45.985 [SSL] ossl_bio_cf_out_write(len=96) -> 96, err=0
CURLINFO_HEADER_OUT: 14.32.45.988 STOR upload-testfile-62b93b39-d523-47b5-89b9-f5d62c58f857.txt.tmp
CURLINFO_TEXT: 14.32.45.991 [FTP] [STOR_TYPE] -> [STOR]
CURLINFO_TEXT: 14.32.45.993 [FTP] [STOR] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.45.996 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.46.019 [FTP] [STOR] ftp_domore_getsock()
CURLINFO_TEXT: 14.32.46.022 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.46.025 [SSL-1] cf_connect()
CURLINFO_TEXT: 14.32.46.028 [TCP-1] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.031 [SSL-1] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.034 [TCP-1] recv(len=3359) -> 3359, err=0
CURLINFO_TEXT: 14.32.46.036 [SSL-1] ossl_bio_cf_in_read(len=3359) -> 3359, err=0
CURLINFO_TEXT: 14.32.46.039 TLSv1.2 (IN), TLS handshake, Server hello (2):
CURLINFO_SSL_DATA_IN: 14.32.46.042 �CURLINFO_TEXT: 14.32.46.045 TLSv1.2 (IN), TLS handshake, Certificate (11):
CURLINFO_SSL_DATA_IN: 14.32.46.047 �CURLINFO_TEXT: 14.32.46.050 TLSv1.2 (IN), TLS handshake, Server key exchange (12):
CURLINFO_SSL_DATA_IN: 14.32.46.053 CURLINFO_TEXT: 14.32.46.056 TLSv1.2 (IN), TLS handshake, Server finished (14):
CURLINFO_SSL_DATA_IN: 14.32.46.059 �CURLINFO_TEXT: 14.32.46.062 TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
CURLINFO_SSL_DATA_OUT: 14.32.46.065 �CURLINFO_TEXT: 14.32.46.069 TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_OUT: 14.32.46.071 �
CURLINFO_TEXT: 14.32.46.074 TLSv1.2 (OUT), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_OUT: 14.32.46.077 �CURLINFO_TEXT: 14.32.46.080 [TCP-1] send(len=93) -> 93, err=0
CURLINFO_TEXT: 14.32.46.083 [SSL-1] ossl_bio_cf_out_write(len=93) -> 93, err=0
CURLINFO_TEXT: 14.32.46.086 [TCP-1] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.46.088 [SSL-1] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.46.091 [SSL-1] cf_connect() -> 0, done=0
CURLINFO_TEXT: 14.32.46.093 [TCP] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.096 [SSL] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.098 [TCP] recv(len=78) -> 78, err=0
CURLINFO_TEXT: 14.32.46.101 [SSL] ossl_bio_cf_in_read(len=78) -> 78, err=0
CURLINFO_TEXT: 14.32.46.103 [SSL] cf_recv(len=900) -> 54, 0
CURLINFO_HEADER_IN: 14.32.46.106 125 Data connection already open; Transfer starting.
CURLINFO_TEXT: 14.32.46.109 [FTP] InitiateTransfer()
CURLINFO_TEXT: 14.32.46.112 [SSL-1] cf_connect()
CURLINFO_TEXT: 14.32.46.116 [TCP-1] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.119 [SSL-1] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.122 [TCP-1] recv(len=1) -> 1, err=0
CURLINFO_TEXT: 14.32.46.125 [SSL-1] ossl_bio_cf_in_read(len=1) -> 1, err=0
CURLINFO_TEXT: 14.32.46.128 TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
CURLINFO_SSL_DATA_IN: 14.32.46.131 �
CURLINFO_TEXT: 14.32.46.135 [TCP-1] recv(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.138 [SSL-1] ossl_bio_cf_in_read(len=5) -> 5, err=0
CURLINFO_TEXT: 14.32.46.141 [TCP-1] recv(len=40) -> 40, err=0
CURLINFO_TEXT: 14.32.46.145 [SSL-1] ossl_bio_cf_in_read(len=40) -> 40, err=0
CURLINFO_TEXT: 14.32.46.149 TLSv1.2 (IN), TLS handshake, Finished (20):
CURLINFO_SSL_DATA_IN: 14.32.46.152 �CURLINFO_TEXT: 14.32.46.155 [SSL-1] Added Session ID to cache for ftp://kamanaftps01.westeurope.cloudapp.azure.com:21 [server]
CURLINFO_TEXT: 14.32.46.158 SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384 / [blank] / UNDEF
CURLINFO_TEXT: 14.32.46.162 Server certificate:
CURLINFO_TEXT: 14.32.46.165 subject: CN=kamanaftps01.westeurope.cloudapp.azure.com
CURLINFO_TEXT: 14.32.46.168 start date: Sep 12 05:59:33 2023 GMT
CURLINFO_TEXT: 14.32.46.171 expire date: Oct 13 05:59:33 2024 GMT
CURLINFO_TEXT: 14.32.46.173 subjectAltName: host "kamanaftps01.westeurope.cloudapp.azure.com" matched cert's "kamanaftps01.westeurope.cloudapp.azure.com"
CURLINFO_TEXT: 14.32.46.182 issuer: C=US; ST=Arizona; L=Scottsdale; O=GoDaddy.com, Inc.; OU=http://certs.godaddy.com/repository/; CN=Go Daddy Secure Certificate Authority - G2
CURLINFO_TEXT: 14.32.46.186 SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
CURLINFO_TEXT: 14.32.46.189 Certificate level 0: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_TEXT: 14.32.46.192 Certificate level 1: Public key type ? (2048/112 Bits/secBits), signed using sha256WithRSAEncryption
CURLINFO_TEXT: 14.32.46.195 [SSL-1] cf_connect() -> 0, done=1
CURLINFO_TEXT: 14.32.46.198 [FTP] [STOR] -> [STOP]
CURLINFO_TEXT: 14.32.46.201 [TCP-1] send(len=95) -> 95, err=0
CURLINFO_TEXT: 14.32.46.204 [SSL-1] ossl_bio_cf_out_write(len=95) -> 95, err=0
CURLINFO_DATA_OUT: 14.32.46.207 This is a testfile created by the Utiliread integration test suite
CURLINFO_TEXT: 14.32.46.210 [TCP-1] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.46.213 [SSL-1] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.46.216 [SSL-1] SSL shutdown not sent, read -> -1
CURLINFO_TEXT: 14.32.46.219 [TCP-1] send(len=31) -> 31, err=0
CURLINFO_TEXT: 14.32.46.221 [SSL-1] ossl_bio_cf_out_write(len=31) -> 31, err=0
CURLINFO_TEXT: 14.32.46.224 TLSv1.2 (OUT), TLS alert, close notify (256):
CURLINFO_SSL_DATA_OUT: 14.32.46.227 �CURLINFO_TEXT: 14.32.46.230 [TCP-1] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.46.233 [SSL-1] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.46.237 [SSL-1] SSL shutdown read -> -1
CURLINFO_TEXT: 14.32.46.240 [SSL-1] SSL shutdown sent, want receive
CURLINFO_TEXT: 14.32.46.243 [SSL-1] cf_shutdown -> 0, done=0
CURLINFO_TEXT: 14.32.46.246 [SSL-1] shut down not done yet
CURLINFO_TEXT: 14.32.46.249 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.47.266 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.47.269 [TCP-1] recv(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.47.271 [SSL-1] ossl_bio_cf_in_read(len=5) -> -1, err=81
CURLINFO_TEXT: 14.32.47.273 [SSL-1] SSL shutdown read -> -1
CURLINFO_TEXT: 14.32.47.275 [SSL-1] SSL shutdown sent, want receive
CURLINFO_TEXT: 14.32.47.277 [SSL-1] cf_shutdown -> 0, done=0
CURLINFO_TEXT: 14.32.47.279 [SSL-1] shut down not done yet
CURLINFO_TEXT: 14.32.47.281 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.48.284 [SSL-1] adjust_pollset, POLLIN fd=1540
CURLINFO_TEXT: 14.32.48.287 SSL shutdown timeout
CURLINFO_TEXT: 14.32.48.288 [FTP] [STOP] closing DATA connection
CURLINFO_TEXT: 14.32.48.291 [TCP-1] cf_socket_close(1540)
CURLINFO_TEXT: 14.32.48.293 [TCP-1] destroy
CURLINFO_TEXT: 14.32.48.295 [FTP] [STOP] done, result=28
CURLINFO_TEXT: 14.32.48.297 closing connection #0
CURLINFO_TEXT: 14.32.48.299 [TCP] cf_socket_close(1560)
CURLINFO_TEXT: 14.32.48.301 [TCP] destroy

[icing]

Thanks! This indeed shows that curl sends the TLS close-notify successfully, but the server just does not responds in the 2 seconds we allow for it. Then we time out.