cURL 7.71 sftp upload slow #5633

RadMission · 2020-06-30T18:21:15Z

I did this

We have a number of daily scheduled tasks which upload files to remote sftp servers, these have been running fine using curl for years now. Recently we tried to upgrade from curl 7.34.0 to 7.71.0 but when running on the new version the files which normally take ~5 min to upload now take 5+ hrs. We're using the exact same command as before:

curl.exe -K "UploadSftp.cURL.config" 2> "..\Logs\UploadSftp.log"

where the config file looks something like this (sensitive information edited out):

upload-file = "~~here be the file path~~"
url = "~~here be the remote server url~~"
user = ~~here be credentials~~
ssl
ftp-pasv
insecure

I expected the following

(what follows is a typical log file with curl 7.34.0)

% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed

0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
0 378M 0 0 0 1984k 0 1186k 0:05:26 0:00:01 0:05:25 1186k
...
99 378M 0 0 99 376M 0 1867k 0:03:27 0:03:26 0:00:01 1734k
100 378M 0 0 100 378M 0 1867k 0:03:27 0:03:27 --:--:-- 1783k

100 378M 0 0 100 378M 0 1867k 0:03:27 0:03:27 --:--:-- 1867k

(where with 7.71.0 we're seeing this)

% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0
0 378M 0 0 0 65536 0 45701 2:24:33 0:00:01 2:24:32 45701
0 378M 0 0 0 65536 0 26914 4:05:27 0:00:02 4:05:25 26914
0 378M 0 0 0 122k 0 36387 3:01:33 0:00:03 3:01:30 36387
0 378M 0 0 0 128k 0 29454 3:44:17 0:00:04 3:44:13 29454
0 378M 0 0 0 128k 0 23979 4:35:30 0:00:05 4:35:25 24385
0 378M 0 0 0 186k 0 29481 3:44:05 0:00:06 3:43:59 24878
...
(On this particular occasion the upload was aborted before finishing)

curl/libcurl version

[curl -V output]

curl 7.71.0 (x86_64-pc-win32) libcurl/7.71.0 OpenSSL/1.1.1g (Schannel) zlib/1.2.11 brotli/1.0.7 WinIDN libssh2/1.9.0 nghttp2/1.41.0
Release-Date: 2020-06-24
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile MultiSSL NTLM SPNEGO SSL SSPI TLS-SRP UnixSockets brotli libz

operating system

Windows Server 2019 Standard
10.0.17763 Build 17763

sterchelen · 2020-06-30T19:16:21Z

Hi @RadMission, huge gap between 7.34.0 and 7.71.0 🙈
Anyway, is it possible to have the verbose output?

RadMission · 2020-06-30T19:50:31Z

Yes, indeed, it's quite a gap.

Here's a verbose output from running a small test file (can't wait 5+ hrs for the full prod file) - everything else is same as with prod:

% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed

0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying ~~host ip and port~~...

Connected to ~~host url~~ (~~host ip~~) port 22 (#0)

0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* SSH MD5 fingerprint: ~~ssh fingerprint in md5 format~~
SSH authentication methods available: password,keyboard-interactive
Initialized password authentication
Authentication complete
} [0 bytes data]

14 454k 0 0 14 65536 0 48943 0:00:09 0:00:01 0:00:08 48943
26 454k 0 0 26 122k 0 53215 0:00:08 0:00:02 0:00:06 53215
28 454k 0 0 28 128k 0 39021 0:00:11 0:00:03 0:00:08 39021
28 454k 0 0 28 128k 0 29877 0:00:15 0:00:04 0:00:11 29877
41 454k 0 0 41 186k 0 35344 0:00:13 0:00:05 0:00:08 36737
42 454k 0 0 42 192k 0 30614 0:00:15 0:00:06 0:00:09 25791
42 454k 0 0 42 192k 0 26418 0:00:17 0:00:07 0:00:10 13985
55 454k 0 0 55 250k 0 30357 0:00:15 0:00:08 0:00:07 24648
56 454k 0 0 56 256k 0 27731 0:00:16 0:00:09 0:00:07 25872
56 454k 0 0 56 256k 0 25030 0:00:18 0:00:10 0:00:08 14029
69 454k 0 0 69 314k 0 28088 0:00:16 0:00:11 0:00:05 24878
70 454k 0 0 70 320k 0 26247 0:00:17 0:00:12 0:00:05 25996
70 454k 0 0 70 320k 0 24286 0:00:19 0:00:13 0:00:06 14104
83 454k 0 0 83 378k 0 26707 0:00:17 0:00:14 0:00:03 24799
84 454k 0 0 84 384k 0 25342 0:00:18 0:00:15 0:00:03 25996
84 454k 0 0 84 384k 0 23802 0:00:19 0:00:16 0:00:03 14070
97 454k 0 0 97 442k 0 25852 0:00:18 0:00:17 0:00:01 24878
98 454k 0 0 98 448k 0 24734 0:00:18 0:00:18 --:--:-- 25934
98 454k 0 0 98 448k 0 23449 0:00:19 0:00:19 --:--:-- 14082* We are completely uploaded and fine

100 454k 0 0 100 454k 0 23756 0:00:19 0:00:19 --:--:-- 17745

100 454k 0 0 100 454k 0 23756 0:00:19 0:00:19 --:--:-- 23756

Connection #0 to host ~~host url~~ left intact

bagder · 2020-06-30T20:59:44Z

This might be a duplicate of #5631 - can you try 7.70.0 and see if that is any different? Otherwise 7.71.1 will be out in ... 9-10 hours or so.

rmja · 2020-07-01T05:58:15Z

@bagder I am seeing the sample problem, and I can confirm that going from 7.71.0 to 7.70.0 resolves the problem. Uploads speeds are reduced from 28 seconds to less than a second.

bagder · 2020-07-01T07:05:40Z

thanks for that @rmja. We've just shipped 7.71.1 now with that particular change reverted so hopefully we're back to proper performance. If @RadMission confirms this to be the same problem we'll consider this case closed.

rmja · 2020-07-01T07:30:54Z

No problem, as soon as I see the official windows build for 7.71.1 on the download page, I will test it and let you know

rmja · 2020-07-01T10:42:08Z

@bagder Upgrading to 7.71.1 did not solve the problem. Uploads with that version are still extremely slow (on Windows). I am back on 7.70.0 for now.

bagder · 2020-07-01T11:13:19Z

Argh, too bad. It would be really helpful if someone could bisect to the offending commit. I still suspect this is a window-specific issue. I'm not on Windows myself.

bagder · 2020-07-01T22:37:46Z

I've not been able to spot any speed difference between 7.68.0 and 7.71.1 when doing sftp upload to localhost on Linux.

jay · 2020-07-02T07:11:47Z

@bagder Upgrading to 7.71.1 did not solve the problem. Uploads with that version are still extremely slow (on Windows). I am back on 7.70.0 for now.

Please give us the full curl -V of the two versions

RadMission · 2020-07-02T15:21:01Z

I can confirm 7.70.0 working as expected.

RadMission · 2020-07-06T18:49:08Z

After discussing with my supervisors, a decision was made to stick with v7.70.0 since it seems to be working fine. Thank you to everyone who contributed here.

mback2k · 2020-07-06T19:57:25Z

I would also be very interested to find out the root cause of this issue if it was not #5397 via #5631 since #5634 is pending now.

Togtja · 2020-07-27T12:42:04Z

I am also experiencing the same as @rmja, that on 7.71.1 uploading using sftp is still super slow. The binary was build on Windows using CMake with these flags set:

#Set CURL setting
set(CMAKE_USE_LIBSSH2 ON) 
set(CURL_ZLIB ON) 
set(CMAKE_USE_OPENSSL ON) 
set(BUILD_CURL_EXE ON) 
set(CURL_STATICLIB ON)

Running the command:
./curl.exe -k -T test.zip sftp://username:password@host_ip:port/path/to/test_of_large_zip_upload.zip
Where the 119 MB file took 1.5 hours, where it normally takes >30s using Filezilla (Or other FTP clients).
I also tried it using libcurl, but same issues applied.

It maxes at around 250 kb/s

mback2k · 2020-07-28T07:44:08Z

@rmja @RadMission @Togtja so all of you are still experiencing slowness with 7.71.1 while not with 7.70.0?

If this is the case, #5397 cannot be the root cause since that has been reverted in 7.71.1. Can one of you bisect the offending commit between these versions maybe? Until this has been solved, I think we should hold of merging #5634 until the next release.

Togtja · 2020-07-28T09:36:46Z

@mback2k When bulding for 7.70.0, just now, I noticed that my CMake script failed. Which made me notice that it failed for 7.71.1, this meant that the executable I was running was actually 7.71.0. After fixing this issue, my curl.exe now uploads at resonable rates. So atleast 7.71.1 fixed it for me.
I am so sorry for the confusion, and it was not curl's CMake files, was a mistake in my own.

RadMission · 2020-07-28T13:03:20Z

…

On Tue, Jul 28, 2020 at 3:44 AM Marc Hörsken ***@***.***> wrote: @rmja <https://github.com/rmja> @RadMission <https://github.com/RadMission> @Togtja <https://github.com/Togtja> so all of you are still experiencing slowness with 7.71.1 while not with 7.70.0? If this is the case, #5397 <#5397> cannot be the root cause since that has been reverted in 7.71.1. Can one of you bisect the offending commit between these versions maybe? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#5633 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABMMFPVLJ2QFIPKFMLJZKCLR5Z6VPANCNFSM4OMQ4IBQ> .

bagder · 2020-07-28T21:33:03Z

So we're back at: 7.71.1 probably is fixed. I say we close this again.

mback2k · 2020-07-29T07:29:26Z

@rmja can you confirm that 7.71.1 also fixed the issue for you so that we can close this again? Above you said that you are still experiencing the issue.

rmja · 2020-07-29T15:23:59Z

I will get back on Saturday, I am currently on offline camping vacation🍺🍻

rmja · 2020-08-03T15:24:52Z

I have just re-done all the tests
7.71.1 54 seconds
7.71.0 54 seconds
7.70.0 14 seconds
7.69.1 14 seconds

mback2k · 2020-08-04T11:34:27Z

This is very interesting. So reverting 8bc25c5 for 7.71.1 did not help you. It seems like your problem is not related to #5631, #5397 or #5634 as your testing there had the same problem. Would you be able to compile yourself and bisect the offending commit?

rmja · 2020-08-04T11:45:21Z

I can try. Can you point me to to some windows build instructions?

mback2k · 2020-08-04T12:27:23Z

I personally use msys2.org to build curl with mingw-w64 using the following autotools steps as given in .azure-pipelines.yml:

./buildconf
./configure --host=x86_64-w64-mingw32 --build=x86_64-w64-mingw32 --prefix=/mingw64 --enable-debug --enable-werror --enable-sspi --without-ssl --with-schannel --with-winidn
make

There are other ways to build on Windows as explained in docs/INSTALL.md, winbuild/BUILD.WINDOWS.txt and projects/README.

jay · 2020-08-04T18:53:29Z

Please refer to the curl wiki how to git bisect.

rmja · 2020-08-05T10:36:46Z

I am trying to produce builds using the following procedure using msys2:

pacman -S base-devel mingw-w64-x86_64-binutils mingw-w64-x86_64-toolchain libssh2-devel mingw-w64-x86_64-libssh2
export PATH="/mingw64/bin:$PATH"
./buildconf
--configure--
make

I have tried A:

./configure --host=x86_64-w64-mingw32 --build=x86_64-w64-mingw32 --prefix=/mingw64 --with-libssh2 --with-winidn

and B:

./configure --host=x86_64-w64-mingw32 --build=x86_64-w64-mingw32 --prefix=/mingw64 --without-ssl --with-schannel --with-winidn

A) produces a build where the easy initialization never completes (the call just never completes), and B) produces a build where I am getting the SSL _CONNECT_ERROR as in the test builds from #5634. What exact configure parameters should i use to get a build with openssl?

rmja · 2020-08-05T12:18:54Z

It seems to be because I am not linking with the correct dependencies:

How do specify that I want to link with the mingw-w64.x86_64 versions which I believe are located in /mingw64/bin?

mback2k · 2020-08-06T13:46:35Z

You need to launch the specific MINGW64 shell instead of the standard MSYS2 shell as seen in purple in your screenshot.

See: https://www.msys2.org/wiki/MSYS2-introduction/#shells

tmkk · 2020-08-07T06:17:59Z

As far as I've tested 7.71.0 and 7.71.1 are good, 7.70.0 is bad. All binaries are from here.

7.70.0: finish instantly

$ ./curl.exe -V && ./curl.exe -T C:/tmp/10M_dummy_file sftp://192.168.1.160/tmp/
curl 7.70.0 (i386-pc-win32) libcurl/7.70.0 OpenSSL/1.1.1g (Schannel) zlib/1.2.11 brotli/1.0.7 WinIDN libssh2/1.9.0 nghttp2/1.40.0
Release-Date: 2020-04-29
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile MultiSSL NTLM SPNEGO SSL SSPI TLS-SRP UnixSockets brotli libz
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 10.0M    0     0  100 10.0M      0  13.4M --:--:-- --:--:-- --:--:-- 13.4M

7.71.0: only 300KiB transferred after 10 seconds

$ ./curl.exe -V && ./curl.exe -T C:/tmp/10M_dummy_file sftp://192.168.1.160/tmp/
curl 7.71.0 (i386-pc-win32) libcurl/7.71.0 OpenSSL/1.1.1g (Schannel) zlib/1.2.11 brotli/1.0.7 WinIDN libssh2/1.9.0 nghttp2/1.41.0
Release-Date: 2020-06-24
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile MultiSSL NTLM SPNEGO SSL SSPI TLS-SRP UnixSockets brotli libz
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  3 10.0M    0     0    3  320k      0  26537  0:06:35  0:00:12  0:06:23 25918

7.71.1: finish instantly

$ ./curl.exe -V && ./curl.exe -T C:/tmp/10M_dummy_file sftp://192.168.1.160/tmp/
curl 7.71.1 (i386-pc-win32) libcurl/7.71.1 OpenSSL/1.1.1g (Schannel) zlib/1.2.11 brotli/1.0.7 WinIDN libssh2/1.9.0 nghttp2/1.41.0
Release-Date: 2020-07-01
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile MultiSSL NTLM SPNEGO SSL SSPI TLS-SRP UnixSockets brotli libz
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 10.0M    0     0  100 10.0M      0  14.3M --:--:-- --:--:-- --:--:-- 14.3M

rmja · 2020-08-07T07:18:00Z

Intermediate update from my side. I have managed to build the source with the following steps:

Install msys2
Run msys2

pacman -S base-devel mingw-w64-x86_64-toolchain mingw-w64-x86_64-binutils libssh2-devel mingw-w64-x86_64-libssh2 zlib-devel mingw-w64-x86_64-zlib openssl-devel mingw-w64-x86_64-openssl

Run mingw64

./buildconf
./configure --host=x86_64-w64-mingw32 --build=x86_64-w64-mingw32 --prefix=/mingw64 --with-libssh2 --with-winidn
make
make install

Inspect ldd /mingw64/bin/libcurl-4.dll | grep -vi System32 and copy all the shown dependencies along with libcurl-4.dll from /mingw64/bin to the test setup.

Some results are:
Current master (865b938) is slow.
Tag 7.71.0 (e9db32a) is slow.
Tag 7.70.0 (53cdc2c) is fast.

I will start the bisect procedure from 53cdc2c to e9db32a now.

rmja · 2020-08-07T11:25:52Z

Here is the bisect result:

aa6cf7f is the last fast commit, f002c85 is the first slow commit.

mback2k · 2020-08-07T11:41:20Z

@bagder would you mind taking a look at this?

bagder · 2020-08-07T12:22:35Z

The f002c85 commit is for FTP so it seems completely unrelated and it is puzzling to me.

@rmja, if you use 7.71.1 as a base and just revert the single commit f002c85 (git revert f002c85), does it make the transfer fast again? I fear it doesn't...

rmja · 2020-08-07T13:23:47Z

@bagder Checking out 7.71.1 (5a1fc8d) and reverting f002c85 fixes the problem for me! It is much (6x) faster.

bagder · 2020-08-07T14:48:08Z

Awesome. But also very strange. I clearly need to dig deeper to understand this...

bagder · 2020-08-07T15:21:01Z

@rmja can you show us a command line you use when you test/verify this? (you can edit out the real host name etc)

rmja · 2020-08-07T15:24:39Z

I am not using the curl command line but I am configuring curl similar to #5634 (comment).

Edit: Note, I cannot test without a proxy, but http and socks5 proxy are equally slow.

mback2k · 2020-08-08T06:59:35Z

@bagder I think @rmja is indeed using FTPS and not SFTP, although this issue was originally just about the later one.

bagder · 2020-08-08T10:46:04Z

That's what I wanted to know. If @rmja sees the difference on FTPS, we're talking about a different issue than this original #5633 one.

bagder · 2020-08-10T09:00:56Z

@rmja your problem is probably fixed in #5798

mback2k · 2020-08-10T09:15:24Z

So I think we can close this SFTP related issue again and focus on #5797 and #5798.

bagder · 2020-08-10T09:32:59Z

Hm, this is #5633... so what did you mean? =)

rmja · 2020-08-10T10:52:03Z

@bagder I can confirm that 8b9dbda in bagder/ftp-close-secondary is fast. Sorry about the confusion on including this in the wrong issue.

mback2k · 2020-08-10T11:07:58Z

Hm, this is #5633... so what did you mean? =)

Sorry, I meant #5797.

bagder added performance SCP/SFTP regression labels Jun 30, 2020

jay added the Windows Windows-specific label Jul 2, 2020

jay added the needs-info label Jul 6, 2020

RadMission closed this as completed Jul 6, 2020

ngg mentioned this issue Jul 10, 2020

multi: implement wait using winsock events #5634

Closed

mback2k reopened this Jul 28, 2020

bagder removed the needs-info label Aug 7, 2020

mback2k closed this as completed Aug 10, 2020

rmja mentioned this issue Aug 10, 2020

ftp: don't do ssl_shutdown instead of ssl_close #5798

Closed

cURL 7.71 sftp upload slow #5633

cURL 7.71 sftp upload slow #5633

Comments

RadMission commented Jun 30, 2020

I did this

I expected the following

curl/libcurl version

operating system

sterchelen commented Jun 30, 2020

RadMission commented Jun 30, 2020

bagder commented Jun 30, 2020

rmja commented Jul 1, 2020

bagder commented Jul 1, 2020

rmja commented Jul 1, 2020

rmja commented Jul 1, 2020

bagder commented Jul 1, 2020

bagder commented Jul 1, 2020

jay commented Jul 2, 2020

RadMission commented Jul 2, 2020

RadMission commented Jul 6, 2020

mback2k commented Jul 6, 2020

Togtja commented Jul 27, 2020 • edited

mback2k commented Jul 28, 2020 • edited

Togtja commented Jul 28, 2020

RadMission commented Jul 28, 2020 via email

bagder commented Jul 28, 2020

mback2k commented Jul 29, 2020

rmja commented Jul 29, 2020

rmja commented Aug 3, 2020

mback2k commented Aug 4, 2020 • edited

rmja commented Aug 4, 2020

mback2k commented Aug 4, 2020 • edited

jay commented Aug 4, 2020

rmja commented Aug 5, 2020

rmja commented Aug 5, 2020

mback2k commented Aug 6, 2020 • edited

tmkk commented Aug 7, 2020

rmja commented Aug 7, 2020

rmja commented Aug 7, 2020

mback2k commented Aug 7, 2020

bagder commented Aug 7, 2020

rmja commented Aug 7, 2020

bagder commented Aug 7, 2020

bagder commented Aug 7, 2020

rmja commented Aug 7, 2020 • edited

mback2k commented Aug 8, 2020

bagder commented Aug 8, 2020

bagder commented Aug 10, 2020

mback2k commented Aug 10, 2020 • edited

bagder commented Aug 10, 2020

rmja commented Aug 10, 2020

mback2k commented Aug 10, 2020 • edited

Togtja commented Jul 27, 2020 •

edited

mback2k commented Jul 28, 2020 •

edited

mback2k commented Aug 4, 2020 •

edited

mback2k commented Aug 4, 2020 •

edited

mback2k commented Aug 6, 2020 •

edited

rmja commented Aug 7, 2020 •

edited

mback2k commented Aug 10, 2020 •

edited

mback2k commented Aug 10, 2020 •

edited