Skip to content

After FTPS upload resumed, XFERINFO function reports ultotal as 0 #8637

Unanswered
ribtoks asked this question in Q&A
After FTPS upload resumed, XFERINFO function reports ultotal as 0 #8637
Mar 25, 2022 · 1 answers · 5 replies

Hello

I'm using libcurl to upload files via FTPS. My uploading code is somewhat based on ftpuploadresume.c, progressfunc.c and debugfunc.c examples (I know I need to provide a minimum viable example, but I'm debugging an error that a user of my app has and thus it's a bit complicated).

During the upload, judging from the logs, there's a connection timeout and after that progress function starts receiving 0 as ultotal parameter all of the time. What could be the reason of such behavior? Can it be a server issue or my misuse of libcurl API or libcurl bug?

libcurl 7.79 with schannel, Windows 10 x64.

Here are the logs:

12:43:38.259 T#28840 reportCurrentFileProgress - 40.0366
12:43:40.261 T#28840 updateProgress - total: 632581154 now: 253755392
12:43:40.261 T#28840 reportCurrentFileProgress - 40.1143
12:43:41.377 T#28840 uploadFile - Attempting to resume: uploaded 0 bytes, try # 1
13:00:24.646 T#28840 updateProgress - total: 0 now: 257916928             <----------------
..... more progress updates ....
13:00:38.941 T#28840 updateProgress - total: 0 now: 261341184             <----------------
13:00:40.951 T#28840 updateProgress - total: 0 now: 261767168             <----------------
13:00:42.957 T#28840 updateProgress - total: 0 now: 262258688             <----------------
13:00:44.451 T#28840 uploadFile - Attempting to resume: uploaded 253853696 bytes, try # 2
13:00:46.580 T#28840 Connectivity::my_trace - "== Info: Found bundle for host ftps.server.com: 0x2164c9a5790 [serially]"
13:00:46.580 T#28840 Connectivity::my_trace - "== Info: Re-using existing connection! (#3) with host ftps.server.com"
13:00:46.580 T#28840 Connectivity::my_trace - "== Info: Connected to ftps.server.com (ip.address) port 21 (#3)"
13:00:46.580 T#28840 Connectivity::my_trace - "== Info: Request has same path as previous transfer"
13:00:46.580 T#28840 Connectivity::dump - "=> Send header, 0000000006 bytes (0x00000006)\nEPSV.."
13:00:46.580 T#28840 Connectivity::my_trace - "== Info: Connect data stream passively"
13:00:46.580 T#28840 Connectivity::my_trace - "== Info: ftp_perform ends with SECONDARY: 0"
13:00:46.686 T#28840 Connectivity::dump - "<= Recv header, 0000000048 bytes (0x00000030)\n229 Entering Extended Passive Mode (|||50648|).."
13:00:46.686 T#28840 Connectivity::my_trace - "== Info: Trying ip.address:50648..."
13:00:46.701 T#28840 Connectivity::my_trace - "== Info: Connecting to ip.address (ip.address) port 50648"
13:01:07.746 T#28840 Connectivity::my_trace - "== Info: connect to ip.address port 21 failed: Timed out"
13:01:07.746 T#28840 Connectivity::my_trace - "== Info: Failed to connect to ftps.server.com port 21 after 21165 ms: Timed out"
13:01:07.746 T#28840 Connectivity::my_trace - "== Info: Failed EPSV attempt. Disabling EPSV"
13:01:07.747 T#28840 Connectivity::dump - "=> Send header, 0000000006 bytes (0x00000006)\nPASV.."
13:01:07.918 T#28840 Connectivity::dump - "<= Recv header, 0000000049 bytes (0x00000031)\n227 Entering Passive Mode (3,87,37,152,195,82)..."
13:01:07.918 T#28840 Connectivity::my_trace - "== Info: Trying ip.address:50002..."
13:01:07.935 T#28840 Connectivity::my_trace - "== Info: Connecting to ip.address (ip.address) port 50002"
13:01:08.086 T#28840 Connectivity::my_trace - "== Info: Connected to ftps.server.com (ip.address) port 21 (#3)"
13:01:08.086 T#28840 Connectivity::dump - "=> Send header, 0000000066 bytes (0x00000042)\nAPPE FILE_NAME.MOV.."
13:01:08.218 T#28840 Connectivity::dump - "<= Recv header, 0000000105 bytes (0x00000069)\n150 Opening BINARY mode data connection for FILE_NAME.MOV.."
13:01:08.218 T#28840 Connectivity::my_trace - "== Info: Doing the SSL/TLS handshake on the data stream"
13:08:51.286 T#28840 Connectivity::my_trace - "== Info: Remembering we are in dir \"\""
13:08:51.286 T#28840 Connectivity::my_trace - "== Info: schannel: shutting down SSL/TLS connection with ftps.server.com port 21"
13:08:51.832 T#28840 Connectivity::dump - "<= Recv header, 0000000023 bytes (0x00000017)\n226 Transfer complete.."
13:08:51.833 T#28840 Connectivity::my_trace - "== Info: Uploaded unaligned file size (0 out of 0 bytes)"
13:08:51.833 T#28840 Connectivity::my_trace - "== Info: Connection #3 to host ftps.server.com left intact"
13:08:51.833 T#28840 logUploadStats - Upload speed for pIi[ "E:/FILE NAME.MOV" ]Iip is 239544 bytes/sec
13:08:51.833 T#28840 logUploadStats - Upload bytes for pIi[ "E:/FILE NAME.MOV" ]Iip is 116239394 bytes
13:08:51.833 T#28840 logUploadStats - Upload time for pIi[ "E:/FILE NAME.MOV" ]Iip is 485 seconds
13:08:51.864 T#28840 uploadFile - Upload failed! Curl error: Transferred a partial file 

Thank you very much for any help.
Taras

Replies

1 suggested answer
·
5 replies

Uploaded unaligned file size (0 out of 0 bytes)

There is a bug in that error message and I've proposed #8649 as a fix. However, even with the fix it will still likely say 0 out of 0 bytes. I'd guess, based on the ftpuploadresume example that you linked to, that your application is manually retrieving the existing size, reading the data to append via readfunction and actually requesting an append via CURLOPT_APPEND. I think in this case the upload total is not known by curl, only your application. @bagder seems that example is outdated, if libcurl always issues SIZE? Couldn't that example just use CURLOPT_APPEND, what is the benefit of manually parsing the size and using a read function in that example?

5 replies
@ribtoks

Hi @bagder. A very kind ping on this. I know how busy you are, but please take a look when you get a chance.

@bagder

I presume that the example is written like this to figure out if it failed the upload because there was already a partial file there, and that's why it does the first check of the size.

@ribtoks I don't know what you want from me on this. ultotal is probably the size you've provided to libcurl in the first place?

@ribtoks

ultotal in logs is correct before libcurl attempts to retry the upload. @bagder I do not "want" anything from you. I would appreciate if you can take a look if there's a bug around that place (in libcurl code) since you might know better than anyone what can go wrong around there.

As for the example, if it is outdated, I would also appreciate some information on what is the "current" way to achieve the same.

Thank you,
Taras

@bagder

I don't know if there's a bug because I don't know how to reproduce the problem you're asking about. I don't see how libcurl can know the ultotal size unless you specify it using the API. Did you?

I don't think the example is "outdated", it uses existing and functional APIs. It might however be a bit quirky and does more than what the name implies.

@ribtoks

Yes, I do specify ultotal using CURLOPT_INFILESIZE_LARGE and I do observe the correct value in logs (progress callback) before the first connection interruption (user internet connection problem). After the first interruption occurs, ultotal that arrives to progress callback function is 0 afterwards.

I know about the reproduction and I'm sorry about that. Sometimes conversation like this might trigger some thoughts so you can understand where can be the problem. But I fully understand and acknowledge that it's only a tiny chance of that without a minimal reproducible example. I myself am "debugging" this problem using only the user-provided logs of my app therefore I also cannot reproduce the problem on my computer.

Thank you

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Category
Q&A
3 participants