Long delay in resuming multi-part uploads after restarting app

[f3n1kc]

Hi,

I am using the AutoResume project (#3474 (comment)) to test uploads for large files (>700mb) on iOS, with latest AWSCore, AWSS3. Everything works fine, except when the app is manually terminated (force stopped). In this case, I noticed a long delay before multipart upload resumes, approximately 3 minutes for a 1.5GB file on the latest iPhones.

According to AWS logs, it seems that the Transfer Utility is waiting for NSURLSession to finish all previously created tasks before it continues:

2023-02-23 12:51:47:562 AutoResume[26624:6570460] Thread:<NSThread: 0x281a87100>{number = 5, name = (null)}: didCompleteWithError called for task 131
2023-02-23 12:51:47:563 AutoResume[26624:6570460] Unable to find information for task 131 in taskDictionary
2023-02-23 12:51:47:563 AutoResume[26624:6570460] Transfer Utility Task not found in taskDictionary ( 131)

My question is: is this expected behavior that after force quitting the app, it takes that long to resume the previously uploaded file?

[f3n1kc]

Adding some additional steps and logs:

1. Run AutoResume from Xcode on device

2. Creating multipart upload with 200 subtasks

2023-03-01 12:52:29:599 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/4B667FEE-2A42-47CC-89A0-973F ... 3DA5.tmp
2023-03-01 12:52:29:633 AutoResume[38221:9622509] Added task for part [1] to inProgress list
2023-03-01 12:52:29:634 AutoResume[38221:9622509] Setting Base URL to Caches Directory: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches
2023-03-01 12:52:29:634 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/61292377-1262-4D0A-8C18-DDD6 ... DA9B.tmp
2023-03-01 12:52:29:660 AutoResume[38221:9622509] Added task for part [2] to inProgress list
2023-03-01 12:52:29:660 AutoResume[38221:9622509] Setting Base URL to Caches Directory: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches
2023-03-01 12:52:29:660 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/DE77FF8F-A90E-48A5-92F6-79FA ... 6265.tmp
2023-03-01 12:52:29:684 AutoResume[38221:9622509] Added task for part [3] to inProgress list
2023-03-01 12:52:29:685 AutoResume[38221:9622509] Setting Base URL to Caches Directory: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches
2023-03-01 12:52:29:685 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/59390CF2-B47A-4D1F-BE86-7393 ... 7C5B.tmp

.......


2023-03-01 12:52:35:590 AutoResume[38221:9622509] Setting Base URL to Caches Directory: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches
2023-03-01 12:52:35:590 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/9E933490-6055-469E-AF51-8DDF ... B4C3.tmp
2023-03-01 12:52:35:605 AutoResume[38221:9622509] Added task for part [198] to Waiting list
2023-03-01 12:52:35:605 AutoResume[38221:9622509] Setting Base URL to Caches Directory: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches
2023-03-01 12:52:35:605 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/1B1A2642-2A2B-4406-8048-6FF5 ... 857E.tmp
2023-03-01 12:52:35:624 AutoResume[38221:9622509] Added task for part [199] to Waiting list
2023-03-01 12:52:35:624 AutoResume[38221:9622509] Setting Base URL to Caches Directory: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches
2023-03-01 12:52:35:624 AutoResume[38221:9622509] Partial File URL: /var/mobile/Containers/Data/Application/894CAECA-9307-4D6E-8DF5-23A7AF146FC2/Library/Caches/437B55AD-2761-402C-A33E-8746 ... 9327.tmp
2023-03-01 12:52:35:637 AutoResume[38221:9622509] Added task for part [200] to Waiting list

2. Upload in progress, 10 subtasks finished

2023-03-01 12:52:39:756 AutoResume[38221:9622509] Thread:<NSThread: 0x2802e4e00>{number = 10, name = (null)}: didCompleteWithError called for task 3
2023-03-01 12:52:40:981 AutoResume[38221:9622859] Thread:<NSThread: 0x2802a3b00>{number = 11, name = (null)}: didCompleteWithError called for task 2
2023-03-01 12:52:41:131 AutoResume[38221:9622859] Thread:<NSThread: 0x2802a3b00>{number = 11, name = (null)}: didCompleteWithError called for task 5
2023-03-01 12:52:41:203 AutoResume[38221:9622509] Thread:<NSThread: 0x2802e4e00>{number = 10, name = (null)}: didCompleteWithError called for task 1
2023-03-01 12:52:41:628 AutoResume[38221:9622859] Thread:<NSThread: 0x2802a3b00>{number = 11, name = (null)}: didCompleteWithError called for task 4
2023-03-01 12:52:43:729 AutoResume[38221:9622825] Thread:<NSThread: 0x280232b00>{number = 13, name = (null)}: didCompleteWithError called for task 147
2023-03-01 12:52:44:575 AutoResume[38221:9622509] Thread:<NSThread: 0x2802e4e00>{number = 10, name = (null)}: didCompleteWithError called for task 144
2023-03-01 12:52:47:282 AutoResume[38221:9622509] Thread:<NSThread: 0x2802e4e00>{number = 10, name = (null)}: didCompleteWithError called for task 52
2023-03-01 12:52:47:431 AutoResume[38221:9622859] Thread:<NSThread: 0x2802a3b00>{number = 11, name = (null)}: didCompleteWithError called for task 193
2023-03-01 12:52:47:739 AutoResume[38221:9622825] Thread:<NSThread: 0x280232b00>{number = 13, name = (null)}: didCompleteWithError called for task 49

3. App terminated from Xcode

4. The app was restarted from Xcode and the upload recovery process has begun. It may take around ~1 minute before it resumes. In the logs, I see multiple errors for finished tasks.:

2023-03-01 12:57:54:872 AutoResume[38274:9625326] Thread:<NSThread: 0x283ff82c0>{number = 5, name = (null)}: didCompleteWithError called for task 383
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Unable to find information for task 383 in taskDictionary
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Transfer Utility Task not found in taskDictionary ( 383)
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Thread:<NSThread: 0x283ff82c0>{number = 5, name = (null)}: didCompleteWithError called for task 202
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Unable to find information for task 202 in taskDictionary
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Transfer Utility Task not found in taskDictionary ( 202)
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Thread:<NSThread: 0x283ff82c0>{number = 5, name = (null)}: didCompleteWithError called for task 203
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Unable to find information for task 203 in taskDictionary
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Transfer Utility Task not found in taskDictionary ( 203)
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Thread:<NSThread: 0x283ff82c0>{number = 5, name = (null)}: didCompleteWithError called for task 204
2023-03-01 12:57:54:872 AutoResume[38274:9625326] Unable to find information for task 204 in taskDictionary

......

2023-03-01 12:58:44:046 AutoResume[38274:9625327] Thread:<NSThread: 0x283ffc800>{number = 6, name = (null)}: didCompleteWithError called for task 265
2023-03-01 12:58:44:046 AutoResume[38274:9625327] Unable to find information for task 265 in taskDictionary
2023-03-01 12:58:44:046 AutoResume[38274:9625327] Transfer Utility Task not found in taskDictionary ( 265)
2023-03-01 12:58:44:186 AutoResume[38274:9625462] Thread:<NSThread: 0x283fefb40>{number = 8, name = (null)}: didCompleteWithError called for task 266
2023-03-01 12:58:44:186 AutoResume[38274:9625462] Unable to find information for task 266 in taskDictionary
2023-03-01 12:58:44:186 AutoResume[38274:9625462] Transfer Utility Task not found in taskDictionary ( 266)
2023-03-01 12:58:44:620 AutoResume[38274:9625462] Thread:<NSThread: 0x283fefb40>{number = 8, name = (null)}: didCompleteWithError called for task 267
2023-03-01 12:58:44:620 AutoResume[38274:9625462] Unable to find information for task 267 in taskDictionary
2023-03-01 12:58:44:620 AutoResume[38274:9625462] Transfer Utility Task not found in taskDictionary ( 267)

Based on the AWSS3TransferUtility code, it appears that all AWSS3TransferUtilityUploadSubTasks are retried from the handleUnlinkedTransfers function, where a new NSURLSessionUploadTask is created for each subtask within the createUploadSubTask function. NSURLSession then waits for all NSURLSessionUploadTasks that were created before the app was killed to finish before continuing with the newly created NSURLSessionUploadTask during multipart upload recovery.

[f3n1kc]

Anyone help?

[pablogeek]

+1

[harsh62]

@f3n1kc Apologies for the delayed response. Our team will try to look into this question and respond soon. Thanks for your patience.

[f3n1kc]

@harsh62 any news?

[harsh62]

@f3n1kc Our team is internally looking into this issue and will provide an update soon.

[kaloramik]

Hi @harsh62 , I'm also experiencing this issue. It seems like the issue gets worse the larger the file is.

I looked at the related issue here #5440 and I am executing block reassignment in the completionHandler, and it does run, but only after a long time, and for a ~7GB file it takes quite some time to reconnect

[tylerjroach]

Thank you for the additional information/context!