Hi Daniel
>From what I saw, timeout messages were always together with "control
>connection looks dead". Regarding upload time, it's hard to answer this
>question, since all uploads failed. I attached a "typical" (from that user)
>log where you can see time to first failure and following failures on your
>own. Log contains only upload thread logs with curl tracing.
I didn't investigate curl commandline tool upload time on my machine since for
me priority #1 is to fix upload errors of users of my app (since they will just
stop using it for upload). I will do so right after finding some solution to
this problem.
I understand about NAT/firewall/etc. timeout, but the thing is that libcurl
7.57 works for them right at the same time (of course, it could be a very big
coincidence). Currently my only option to be "on the safe side" is to downgrade
back, however, I'm still hesitating.
So far I will try to disable UPLOAD_BUFFERSIZE setting and increase
CURLOPT_FTP_RESPONSE_TIMEOUT and see if it will help.
Best regards,
Taras Kushnir
________________________________
From: Daniel Stenberg <dan...@haxx.se>
Sent: Friday, July 19, 2019 10:33 AM
To: Taras Kushnir
Cc: curl-library@cool.haxx.se; Daniel Jeliński
Subject: Re: How to do optimal FTP upload for multiple files?
On Fri, 19 Jul 2019, Taras Kushnir wrote:
> On the same machine at the same time, app with libcurl 7.57 uploads without
> timeout and app with libcurl 7.65 and UPLOAD_BUFFERSIZE change uploads with
> timeout.
And how long did the uploads take in both these cases? Was the timeout always
the control connection one Daniel showed?
> Since I’m not a big expert in libcurl (that’s why I’m seeking your help in
> this mailing list) of course I thought that UPLOAD_BUFFERSIZE is the problem
> (because that’s all that I personally changed).
I understand that, but it is important to keep an eye on *all* the details and
facts so that we don't accidentally focus on the wrong things.
If changing UPLOAD_BUFFERSIZE actually makes the upload slower, it can of
course explain why the control connection would time out if that slowness
pushes the transfer time over the "magic threshold" (which to us happens to be
unknown). It of course doesn't at all explain *why* changing that size makes
the upload slower, because as I've said already, it really shouldn't.
If you do FTP upload with the curl command line tool, does it also show the
same kind of "slowness" ?
> Of course, I can just try to increase the timeout in my app and see if it
> helps, but at least it’s important (and interesting) to understand “why?”.
The timeout in question here is most likely in a router, NAT or firewall
between the client and the server so there's no timeout in the app that you
can change for this!
--
/ daniel.haxx.se | Get the best commercial curl support there is - from me
| Private help, bug fixes, support, ports, new features
| https://www.wolfssl.com/contact/
18:17:06.486 T#11096 libxpks::net::FtpUploaderWorker::process - Waiting for the
semaphore "ftp.contributor.adobestock.com"
18:17:06.486 T#11096 libxpks::net::FtpUploaderWorker::process - Starting upload
to "ftp.contributor.adobestock.com"
18:17:06.486 T#11096 libxpks::net::CurlFtpUploader::uploadBatch - Uploading 1
file(s) started for "ftp.contributor.adobestock.com/" Passive mode = true
18:17:06.486 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 0 lastProgress: 1e-06
18:17:06.486 T#11096 libxpks::net::uploadFile - "C:/Users/LEO
78/Pictures/P7030077.JPG" --> "ftp.contributor.adobestock.com/P7030077.JPG"
18:17:06.486 T#11096 libxpks::net::uploadFile - Setting buffersize to 2097152
bytes
18:17:06.502 T#11096 Connectivity::my_trace - "== Info: Trying
31.25.82.17:21..."
18:17:06.502 T#11096 Connectivity::my_trace - "== Info: TCP_NODELAY set"
18:17:06.580 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#0)"
18:17:06.658 T#11096 Connectivity::dump - "<= Recv header, 0000000129 bytes
(0x00000081)\n220 Welcome to ftp.contributor.adobestock.com, instructions can
be found in https://contributor.stock.adobe.com/tips-and-guides..";
18:17:06.658 T#11096 Connectivity::dump - "=> Send header, 0000000016 bytes
(0x00000010)\nUSER 208523176.."
18:17:06.736 T#11096 Connectivity::dump - "<= Recv header, 0000000037 bytes
(0x00000025)\n331 Password required for 208523176.."
18:17:06.736 T#11096 Connectivity::dump - "Password token hidden here"
18:17:06.884 T#11096 Connectivity::dump - "<= Recv header, 0000000030 bytes
(0x0000001e)\n230 User 208523176 logged in.."
18:17:06.884 T#11096 Connectivity::dump - "=> Send header, 0000000005 bytes
(0x00000005)\nPWD.."
18:17:06.962 T#11096 Connectivity::dump - "<= Recv header, 0000000034 bytes
(0x00000022)\n257 \"/\" is the current directory.."
18:17:06.962 T#11096 Connectivity::my_trace - "== Info: Entry path is '/'"
18:17:06.962 T#11096 Connectivity::dump - "=> Send header, 0000000006 bytes
(0x00000006)\nEPSV.."
18:17:06.962 T#11096 Connectivity::my_trace - "== Info: Connect data stream
passively"
18:17:06.962 T#11096 Connectivity::my_trace - "== Info: ftp_perform ends with
SECONDARY: 0"
18:17:07.040 T#11096 Connectivity::dump - "<= Recv header, 0000000048 bytes
(0x00000030)\n229 Entering Extended Passive Mode (|||63974|).."
18:17:07.040 T#11096 Connectivity::my_trace - "== Info: Trying
31.25.82.17:63974..."
18:17:07.040 T#11096 Connectivity::my_trace - "== Info: TCP_NODELAY set"
18:17:07.056 T#11096 Connectivity::my_trace - "== Info: Connecting to
31.25.82.17 (31.25.82.17) port 63974"
18:17:07.134 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#0)"
18:17:07.134 T#11096 Connectivity::dump - "=> Send header, 0000000008 bytes
(0x00000008)\nTYPE I.."
18:17:07.212 T#11096 Connectivity::dump - "<= Recv header, 0000000019 bytes
(0x00000013)\n200 Type set to I.."
18:17:07.212 T#11096 Connectivity::dump - "=> Send header, 0000000019 bytes
(0x00000013)\nSTOR P7030077.JPG.."
18:17:07.321 T#11096 Connectivity::dump - "<= Recv header, 0000000058 bytes
(0x0000003a)\n150 Opening BINARY mode data connection for P7030077.JPG.."
18:17:11.333 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:13.333 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:15.333 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:17.334 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:19.334 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:21.334 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:23.334 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:25.346 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:27.359 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:29.359 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:31.359 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:33.359 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:35.360 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:17:59.392 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:01.401 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:03.406 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:05.406 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:08.407 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:10.407 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:12.407 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 67.7055 lastProgress: 67.7055
18:18:13.423 T#11096 Connectivity::my_trace - "== Info: We are completely
uploaded and fine"
18:18:13.423 T#11096 Connectivity::my_trace - "== Info: Remembering we are in
dir \"\""
18:18:16.433 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 100 lastProgress: 100
18:18:18.433 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 100 lastProgress: 100
18:18:20.433 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 100 lastProgress: 100
18:18:22.433 T#11096 libxpks::net::CurlFtpUploader::reportCurrentFileProgress -
newProgress: 100 lastProgress: 100
18:18:23.449 T#11096 Connectivity::my_trace - "== Info: FTP response timeout"
18:18:23.449 T#11096 Connectivity::my_trace - "== Info: control connection
looks dead"
18:18:23.449 T#11096 Connectivity::my_trace - "== Info: Closing connection 0"
18:18:23.449 T#11096 libxpks::net::uploadFile - Attempting to resume upload 0
try # 1
18:18:23.449 T#11096 libxpks::net::uploadFile - Setting buffersize to 1048576
bytes
18:18:23.449 T#11096 Connectivity::my_trace - "== Info: Trying
31.25.82.17:21..."
18:18:23.449 T#11096 Connectivity::my_trace - "== Info: TCP_NODELAY set"
18:18:23.714 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#1)"
18:18:23.980 T#11096 Connectivity::dump - "<= Recv header, 0000000129 bytes
(0x00000081)\n220 Welcome to ftp.contributor.adobestock.com, instructions can
be found in https://contributor.stock.adobe.com/tips-and-guides..";
18:18:23.980 T#11096 Connectivity::dump - "=> Send header, 0000000016 bytes
(0x00000010)\nUSER 208523176.."
18:18:24.089 T#11096 Connectivity::dump - "<= Recv header, 0000000037 bytes
(0x00000025)\n331 Password required for 208523176.."
18:18:24.089 T#11096 Connectivity::dump - "Password token hidden here"
18:18:25.355 T#11096 Connectivity::dump - "<= Recv header, 0000000030 bytes
(0x0000001e)\n230 User 208523176 logged in.."
18:18:25.355 T#11096 Connectivity::dump - "=> Send header, 0000000005 bytes
(0x00000005)\nPWD.."
18:18:25.763 T#11096 Connectivity::dump - "<= Recv header, 0000000034 bytes
(0x00000022)\n257 \"/\" is the current directory.."
18:18:25.763 T#11096 Connectivity::my_trace - "== Info: Entry path is '/'"
18:18:25.763 T#11096 Connectivity::dump - "=> Send header, 0000000008 bytes
(0x00000008)\nTYPE I.."
18:18:25.763 T#11096 Connectivity::my_trace - "== Info: ftp_perform ends with
SECONDARY: 0"
18:18:25.935 T#11096 Connectivity::dump - "<= Recv header, 0000000019 bytes
(0x00000013)\n200 Type set to I.."
18:18:25.935 T#11096 Connectivity::dump - "=> Send header, 0000000019 bytes
(0x00000013)\nSIZE P7030077.JPG.."
18:18:26.076 T#11096 Connectivity::dump - "<= Recv header, 0000000045 bytes
(0x0000002d)\n550 P7030077.JPG: No such file or directory.."
18:18:26.076 T#11096 Connectivity::dump - "=> Send header, 0000000008 bytes
(0x00000008)\nREST 0.."
18:18:26.154 T#11096 Connectivity::dump - "<= Recv header, 0000000066 bytes
(0x00000042)\n350 Restarting at 0. Send STORE or RETRIEVE to initiate
transfer.."
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Remembering we are in
dir \"\""
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Connection #1 to host
ftp.contributor.adobestock.com left intact"
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Found bundle for host
ftp.contributor.adobestock.com: 0x204c71de160 [serially]"
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Re-using existing
connection! (#1) with host ftp.contributor.adobestock.com"
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#1)"
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Request has same path
as previous transfer"
18:18:26.154 T#11096 Connectivity::dump - "=> Send header, 0000000006 bytes
(0x00000006)\nEPSV.."
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: Connect data stream
passively"
18:18:26.154 T#11096 Connectivity::my_trace - "== Info: ftp_perform ends with
SECONDARY: 0"
18:18:26.247 T#11096 Connectivity::dump - "<= Recv header, 0000000048 bytes
(0x00000030)\n229 Entering Extended Passive Mode (|||64572|).."
18:18:26.247 T#11096 Connectivity::my_trace - "== Info: Trying
31.25.82.17:64572..."
18:18:26.247 T#11096 Connectivity::my_trace - "== Info: TCP_NODELAY set"
18:18:26.247 T#11096 Connectivity::my_trace - "== Info: Connecting to
31.25.82.17 (31.25.82.17) port 64572"
18:18:26.341 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#1)"
18:18:26.341 T#11096 Connectivity::dump - "=> Send header, 0000000019 bytes
(0x00000013)\nAPPE P7030077.JPG.."
18:18:26.451 T#11096 Connectivity::dump - "<= Recv header, 0000000058 bytes
(0x0000003a)\n150 Opening BINARY mode data connection for P7030077.JPG.."
18:22:41.782 T#11096 Connectivity::my_trace - "== Info: Remembering we are in
dir \"\""
18:22:51.797 T#11096 Connectivity::my_trace - "== Info: FTP response timeout"
18:22:51.797 T#11096 Connectivity::my_trace - "== Info: control connection
looks dead"
18:22:51.797 T#11096 Connectivity::my_trace - "== Info: Closing connection 1"
18:22:51.797 T#11096 libxpks::net::uploadFile - Attempting to resume upload 0
try # 2
18:22:51.797 T#11096 libxpks::net::uploadFile - Setting buffersize to 524288
bytes
18:22:51.797 T#11096 Connectivity::my_trace - "== Info: Trying
31.25.82.17:21..."
18:22:51.797 T#11096 Connectivity::my_trace - "== Info: TCP_NODELAY set"
18:22:52.031 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#2)"
18:22:52.390 T#11096 Connectivity::dump - "<= Recv header, 0000000129 bytes
(0x00000081)\n220 Welcome to ftp.contributor.adobestock.com, instructions can
be found in https://contributor.stock.adobe.com/tips-and-guides..";
18:22:52.390 T#11096 Connectivity::dump - "=> Send header, 0000000016 bytes
(0x00000010)\nUSER 208523176.."
18:22:52.609 T#11096 Connectivity::dump - "<= Recv header, 0000000037 bytes
(0x00000025)\n331 Password required for 208523176.."
18:22:52.609 T#11096 Connectivity::dump - "Password token hidden here"
18:22:52.953 T#11096 Connectivity::dump - "<= Recv header, 0000000030 bytes
(0x0000001e)\n230 User 208523176 logged in.."
18:22:52.953 T#11096 Connectivity::dump - "=> Send header, 0000000005 bytes
(0x00000005)\nPWD.."
18:22:53.266 T#11096 Connectivity::dump - "<= Recv header, 0000000034 bytes
(0x00000022)\n257 \"/\" is the current directory.."
18:22:53.266 T#11096 Connectivity::my_trace - "== Info: Entry path is '/'"
18:22:53.266 T#11096 Connectivity::dump - "=> Send header, 0000000008 bytes
(0x00000008)\nTYPE I.."
18:22:53.266 T#11096 Connectivity::my_trace - "== Info: ftp_perform ends with
SECONDARY: 0"
18:22:53.453 T#11096 Connectivity::dump - "<= Recv header, 0000000019 bytes
(0x00000013)\n200 Type set to I.."
18:22:53.453 T#11096 Connectivity::dump - "=> Send header, 0000000019 bytes
(0x00000013)\nSIZE P7030077.JPG.."
18:22:53.641 T#11096 Connectivity::dump - "<= Recv header, 0000000045 bytes
(0x0000002d)\n550 P7030077.JPG: No such file or directory.."
18:22:53.641 T#11096 Connectivity::dump - "=> Send header, 0000000008 bytes
(0x00000008)\nREST 0.."
18:22:53.797 T#11096 Connectivity::dump - "<= Recv header, 0000000066 bytes
(0x00000042)\n350 Restarting at 0. Send STORE or RETRIEVE to initiate
transfer.."
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Remembering we are in
dir \"\""
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Connection #2 to host
ftp.contributor.adobestock.com left intact"
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Found bundle for host
ftp.contributor.adobestock.com: 0x204b627df70 [serially]"
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Re-using existing
connection! (#2) with host ftp.contributor.adobestock.com"
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#2)"
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Request has same path
as previous transfer"
18:22:53.797 T#11096 Connectivity::dump - "=> Send header, 0000000006 bytes
(0x00000006)\nEPSV.."
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: Connect data stream
passively"
18:22:53.797 T#11096 Connectivity::my_trace - "== Info: ftp_perform ends with
SECONDARY: 0"
18:22:53.891 T#11096 Connectivity::dump - "<= Recv header, 0000000048 bytes
(0x00000030)\n229 Entering Extended Passive Mode (|||55357|).."
18:22:53.891 T#11096 Connectivity::my_trace - "== Info: Trying
31.25.82.17:55357..."
18:22:53.891 T#11096 Connectivity::my_trace - "== Info: TCP_NODELAY set"
18:22:53.891 T#11096 Connectivity::my_trace - "== Info: Connecting to
31.25.82.17 (31.25.82.17) port 55357"
18:22:54.031 T#11096 Connectivity::my_trace - "== Info: Connected to
ftp.contributor.adobestock.com (31.25.82.17) port 21 (#2)"
18:22:54.031 T#11096 Connectivity::dump - "=> Send header, 0000000019 bytes
(0x00000013)\nAPPE P7030077.JPG.."
18:22:54.187 T#11096 Connectivity::dump - "<= Recv header, 0000000058 bytes
(0x0000003a)\n150 Opening BINARY mode data connection for P7030077.JPG.."
18:25:53.547 T#11096 Connectivity::my_trace - "== Info: Remembering we are in
dir \"\""
18:26:03.563 T#11096 Connectivity::my_trace - "== Info: FTP response timeout"
18:26:03.563 T#11096 Connectivity::my_trace - "== Info: control connection
looks dead"
18:26:03.563 T#11096 Connectivity::my_trace - "== Info: Closing connection 2"
18:26:03.563 T#11096 libxpks::net::uploadFile - Upload failed! Curl error:
Timeout was reached
18:26:03.563 T#11096 libxpks::net::CurlFtpUploader::uploadBatch - Uploading
finished for "ftp.contributor.adobestock.com/"
18:26:03.563 T#11096 libxpks::net::FtpUploaderWorker::process - Released
semaphore "ftp.contributor.adobestock.com"
18:26:03.563 T#11096 libxpks::net::UploadContext::~UploadContext - destructor
for host "ftp.contributor.adobestock.com"
-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.haxx.se/mail/etiquette.html
