[S3] `uploadFile` uploads successfully a `0` bytes length file only from device #4327

dsaliberti · 2022-09-23T10:31:24Z

Describe the bug
All videos uploaded from the Simulator do work correctly: I see the upload request with expected bytes (non-zero):

Content-Length	2690127

Tho short videos, with some seconds duration uploads successfully (status code 200) but 0 bytes on the s3 request:

Content-Length	0

This also happens on some types of videos like some Live Photos with loop or bounce style. But it's easier to spot with any short video.

To Reproduce
Steps to reproduce the behavior:

Upload using S3 a 2 seconds video from Simulator, works fine ✓
Upload using S3 the same video from device, seems fine but bytes are zeroed 💥

Observed Behavior

0 bytes on certain video uploads

Expected Behavior

The full content should be uploaded

Unique Configuration

"S3TransferUtility": {
                    "Default": {
                        "Bucket": "my-bucket-here",
                        "Region": "xx-yyyy-1"
                    }
                }

"storage": {
        "plugins": {
            "awsS3StoragePlugin": {
                "bucket": "my-bucket-here",
                "region": "xx-yyyy-1",
                "defaultAccessLevel": "guest"
            }
        }
    }

Areas of the SDK you are using (AWSMobileClient, Cognito, Pinpoint, IoT, etc)?

S3 Storage uploadFile - but also uses Cognito and Datastore

Environment(please complete the following information):

SDK Version: [e.g. 2.6.29]
- from Podfile.lock

  - Amplify (1.24.0):
    - Amplify/Default (= 1.24.0)
  - Amplify/Default (1.24.0)
  - Amplify/Tools (1.24.0)
  - AmplifyPlugins/AWSAPIPlugin (1.24.0):
    - AppSyncRealTimeClient (~> 1.8)
    - AWSCore (~> 2.27.0)
    - AWSPluginsCore (= 1.24.0)
  - AmplifyPlugins/AWSCognitoAuthPlugin (1.24.0):
    - AWSAuthCore (~> 2.27.0)
    - AWSCognitoIdentityProvider (~> 2.27.0)
    - AWSCognitoIdentityProviderASF (~> 2.27.0)
    - AWSCore (~> 2.27.0)
    - AWSMobileClient (~> 2.27.0)
    - AWSPluginsCore (= 1.24.0)
  - AmplifyPlugins/AWSDataStorePlugin (1.24.0):
    - AWSCore (~> 2.27.0)
    - AWSPluginsCore (= 1.24.0)
    - SQLite.swift (= 0.13.2)
  - AmplifyPlugins/AWSS3StoragePlugin (1.24.0):
    - AWSCore (~> 2.27.0)
    - AWSPluginsCore (= 1.24.0)
    - AWSS3 (~> 2.27.

Dependency Manager: Cocoapods
Swift Version : 5
Xcode Version: 14

Device Information (please complete the following information):

Device: iPhone 13 Pro, Simulator (any)
iOS Version: 16
Specific to simulators: any Simulator - but iPhone 14 Pro Max works

Additional context
Everything looks correct in the logs. Just the video content-length is 0
I reproduce it at any time!

Thanks in advance

The text was updated successfully, but these errors were encountered:

dsaliberti · 2022-09-23T12:57:39Z

Similar to this one #1707 but I can reproduce 💯
@palpatim

atierian · 2022-09-23T13:41:01Z

Thanks for opening this issue @dsaliberti.
Can you confirm which uploadFile API you're using, is itAmplify.Storage or AWSS3TransferUtility?
The current version of Amplify is 1.28.1, can you update to this version and see if the issue persists?
You mentioned that everything looks correct in the logs, can you paste those here?

Logs guidance - sensitive information
Logs guidance - collapsible details

dsaliberti · 2022-09-23T13:53:05Z

maybe this - almost 10 years old - issue on JQueryFileUpload - has somehow some clue?

I can also confirm that removing "multiple" from the input tag does seem to fix the issue

maybe we can somehow handle the equivalent "multiple" or multipart from client? 🤔

blueimp/jQuery-File-Upload#2627

dsaliberti · 2022-09-23T13:54:35Z

Thanks for opening this issue @dsaliberti. Can you confirm which uploadFile API you're using, is itAmplify.Storage or AWSS3TransferUtility? The current version of Amplify is 1.28.1, can you update to this version and see if the issue persists? You mentioned that everything looks correct in the logs, can you paste those here?

Logs guidance - sensitive information Logs guidance - collapsible details

@atierian
Amplify.Storage.uploadFile

Amplify.Storage.uploadFile(
    key: key,
    local: local,
    options: options,
    progressListener: progressListener
  )

dsaliberti · 2022-09-23T14:31:43Z

@atierian Just tried to use 1.28.1 and got some unrelated errors on our Appsync models
Property 'identifier' must be declared public because it matches a requirement in public protocol 'Model'
so I think a simple version bump will bring other side effects to be addressed in a separate context

atierian · 2022-09-23T14:42:13Z

Interesting, thanks for sharing. That shouldn't happen, I opened aws-amplify/amplify-swift#2345 to track it. If you could provide any additional context there, like where that error is originating, it would be helpful.

As to the upload issue, can you post the logs here after setting Amplify.Logging.logLevel = .verbose ? That would be helpful for us to try to create a proper repro.

dsaliberti · 2022-09-23T15:16:49Z

I just built using 1.27.1 and it was the same: 0 bytes for small videos from device

Regarding the logs I mentioned previously, it's not something relevant but just what I printed from the progressListener and completion handlers:

On device iPhone 13 Pro:

-> video upload progress 0.0
-> video upload completed ✓

and on the other hand, on Simulator we see:

-> video upload progress 1.0
-> video upload completed ✓

for the exact same video file.

Given my previous comment I'll need to pull and generate my AppSync models in order to use Amplify 1.28.1

Thanks again @atierian

dsaliberti · 2022-09-26T10:42:26Z

As to the upload issue, can you post the logs here after setting Amplify.Logging.logLevel = .verbose ? That would be helpful for us to try to create a proper repro.

@atierian here follows the logs right before and after the 0 bytes upload happens...
I redacted and renamed as much as I could in the snippet below, as well as added some comments (starting with >>>>>>>>>>>> )

I think the verbose logs didn't add anything new given it's majority (if not all) related to Datastore rather than S3Storage

Log Messages

2022-09-26 10:49:37.385896+0100 MyApp Staging[3390:1147639] [AXRuntimeCommon] Unknown client: MyApp Staging
CoreData: annotation: Core Data multi-threading assertions enabled.
2022-09-26 10:49:42.971614+0100 MyApp Staging[3390:1147647] [core] "Error returned from daemon: Error Domain=com.apple.accounts Code=7 "(null)""
2022-09-26 10:49:42.982270+0100 MyApp Staging[3390:1147650] [PAAccessLogger] Failed to log access with error: access=<PATCCAccess 0x280f51220> accessor:<<PAApplication 0x280f77d40 identifierType:auditToken identifier:{pid:3390, version:9629}>> identifier:D910726F-2BD5-4AB3-BB7B-76A1F74EDEA6 kind:intervalEvent timestampAdjustment:0 visibilityState:0 assetIdentifierCount:0 tccService:kTCCServicePhotos, error=Error Domain=NSCocoaErrorDomain Code=4097 "connection to service with pid 1714 named com.apple.privacyaccountingd" UserInfo={NSDebugDescription=connection to service with pid 1714 named com.apple.privacyaccountingd}
2022-09-26 10:49:42.985  ℹ️ INFO: -> didPickMedia local url trim.EB7048E9-F63F-4101-AA24-40BB96DB2771.MOV
[MyApp]: -> didPickMedia local url trim.EB7048E9-F63F-4101-AA24-40BB96DB2771.MOV
2022-09-26 10:49:43.881116+0100 MyApp Staging[3390:1147327] [api] -[CIImage initWithCVPixelBuffer:options:] failed because the buffer is nil.
2022-09-26 10:49:43.952498+0100 MyApp Staging[3390:1147647] [TextIdentificationService] Text LID dominant failure: lidInconclusive
2022-09-26 10:49:43.953366+0100 MyApp Staging[3390:1147893] [VisualTranslationService] Visual isTranslatable: NO; not offering translation: lidInconclusive
2022-09-26 10:49:44.930765+0100 MyApp Staging[3390:1147637] Metal API Validation Enabled
[MyApp]: -> video upload s3key mymodels/A3764306-5ED7-4A32-A91B-2757C5A61E1D/57C2339C-E35D-4730-B461-B50D4C250770.trim.EB7048E9-F63F-4101-AA24-40BB96DB2771.MOV
2022-09-26 10:49:54.371  ℹ️ INFO: -> video upload s3key mymodels/A3764306-5ED7-4A32-A91B-2757C5A61E1D/57C2339C-E35D-4730-B461-B50D4C250770.trim.EB7048E9-F63F-4101-AA24-40BB96DB2771.MOV
2022-09-26 10:49:54.376768+0100 MyApp Staging[3390:1147327] [AWSDataStorePlugin] Saving: MediaFile(id: "57C2339C-E35D-4730-B461-B50D4C250770", ...... redacted properties) with condition: nil
2022-09-26 10:49:54.379544+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select count(id) from "MediaFile" where id = '57C2339C-E35D-4730-B461-B50D4C250770'
2022-09-26 10:49:54.381423+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select count(id) from "MediaFile" where id = '57C2339C-E35D-4730-B461-B50D4C250770'
2022-09-26 10:49:54.381590+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select count(id) from "MediaFile" where id = '57C2339C-E35D-4730-B461-B50D4C250770'
2022-09-26 10:49:54.382969+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] insert into "MediaFile" ("id", ...... redacted properties)
values ('57C2339C-E35D-4730-B461-B50D4C250770' ...... redacted properties)
2022-09-26 10:49:54.390406+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", ...... redacted properties
from "MediaFile" as "root"
where 1 = 1
  and "root"."id" = '57C2339C-E35D-4730-B461-B50D4C250770'
2022-09-26 10:49:54.390529+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", ...... redacted properties
from "MediaFile" as "root"
where 1 = 1
  and "root"."id" = '57C2339C-E35D-4730-B461-B50D4C250770'
2022-09-26 10:49:54.397136+0100 MyApp Staging[3390:1147327] [StorageEngine] save(_:modelSchema:condition:completion:) syncing mutation for MediaFile(id: "57C2339C-E35D-4730-B461-B50D4C250770", ...... redacted properties)

2022-09-26 10:49:54.403407+0100 MyApp Staging[3390:1147327] [AWSMutationDatabaseAdapter] submit(mutationEvent:): MutationEvent(id: "10B41BD9-1F22-44FD-85F0-A67755FEE516", modelId: "57C2339C-E35D-4730-B461-B50D4C250770", modelName: "MediaFile", json: "{...... redacted properties}", mutationType: "create", createdAt: Amplify.Temporal.DateTime(foundationDate: 2022-09-26 09:49:54 +0000, localTimezone: nil), version: nil, inProcess: false, graphQLFilterJSON: nil)
2022-09-26 10:49:54.404134+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."deleted" as "deleted", "root"."lastChangedAt" as "lastChangedAt",
  "root"."version" as "version"
from "MutationSyncMetadata" as "root"
where 1 = 1
  and (
    "root"."id" = 'MediaFile|57C2339C-E35D-4730-B461-B50D4C250770'
  )

...

2022-09-26 10:49:54.405952+0100 MyApp Staging[3390:1147327] [AWSMutationDatabaseAdapter] disposition(for:given:) no local events, saving candidate
2022-09-26 10:49:54.407035+0100 MyApp Staging[3390:1147327] [AWSMutationDatabaseAdapter] resolve(candidate:localEvents:per:storageAdapter:completionPromise:) disposition saveCandidate
2022-09-26 10:49:54.407135+0100 MyApp Staging[3390:1147327] [AWSMutationDatabaseAdapter] save(mutationEvent:storageAdapter:completionPromise:) mutationEvent: MutationEvent(id: "10B41BD9-1F22-44FD-85F0-A67755FEE516", modelId: "57C2339C-E35D-4730-B461-B50D4C250770", modelName: "MediaFile", json: "{ ...... redacted properties}", mutationType: "create", createdAt: Amplify.Temporal.DateTime(foundationDate: 2022-09-26 09:49:54 +0000, localTimezone: nil), version: nil, inProcess: false, graphQLFilterJSON: nil)
2022-09-26 10:49:54.407208+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select count(id) from "MutationEvent" where id = '10B41BD9-1F22-44FD-85F0-A67755FEE516'

...

2022-09-26 10:49:54.412166+0100 MyApp Staging[3390:1147327] [AWSMutationDatabaseAdapter] save(mutationEvent:storageAdapter:completionPromise:): saved MutationEvent(id: "10B41BD9-1F22-44FD-85F0-A67755FEE516", modelId: "57C2339C-E35D-4730-B461-B50D4C250770", modelName: "MediaFile", json: "{ ...... redacted properties }", mutationType: "create", createdAt: Amplify.Temporal.DateTime(foundationDate: 2022-09-26 09:49:54 +0000, localTimezone: Optional(GMT (fixed))), version: nil, inProcess: true, graphQLFilterJSON: nil)

...

2022-09-26 10:49:54.413378+0100 MyApp Staging[3390:1147327] [OutgoingMutationQueue] receive(_:)
2022-09-26 10:49:54.413395+0100 MyApp Staging[3390:1147327] [OutgoingMutationQueue] enqueue(_:)
2022-09-26 10:49:54.417463+0100 MyApp Staging[3390:1147327] [StateMachine<State, Action>] Notifying: enqueuedEvent
2022-09-26 10:49:54.417854+0100 MyApp Staging[3390:1147637] [SyncMutationToCloudOperation] main()
2022-09-26 10:49:54.417905+0100 MyApp Staging[3390:1147637] [SyncMutationToCloudOperation] sendMutationToCloud(withAuthType:)
2022-09-26 10:49:54.418599+0100 MyApp Staging[3390:1147327] [StateMachine<State, Action>] resolve(requestingEvent, enqueuedEvent) -> waitingForEventToProcess
2022-09-26 10:49:54.418632+0100 MyApp Staging[3390:1147327] [OutgoingMutationQueue] New state: waitingForEventToProcess
2022-09-26 10:49:54.419879+0100 MyApp Staging[3390:1147327] [AWSMutationDatabaseAdapter] save(mutationEvent:storageAdapter:completionPromise:): invoking completionPromise with success(Amplify.MutationEvent(id: "10B41BD9-1F22-44FD-85F0-A67755FEE516", modelId: "57C2339C-E35D-4730-B461-B50D4C250770", modelName: "MediaFile", json: "{ ...... redacted properties }", mutationType: "create", createdAt: Amplify.Temporal.DateTime(foundationDate: 2022-09-26 09:49:54 +0000, localTimezone: Optional(GMT (fixed))), version: nil, inProcess: true, graphQLFilterJSON: nil))

2022-09-26 10:49:54.420074+0100 MyApp Staging[3390:1147327] [StorageEngine] submitToSyncEngine(mutationEvent:syncEngine:completion:) saved mutation event: MutationEvent(id: "10B41BD9-1F22-44FD-85F0-A67755FEE516", modelId: "57C2339C-E35D-4730-B461-B50D4C250770", modelName: "MediaFile", json: "{ ...... redacted properties }", mutationType: "create", createdAt: Amplify.Temporal.DateTime(foundationDate: 2022-09-26 09:49:54 +0000, localTimezone: Optional(GMT (fixed))), version: nil, inProcess: true, graphQLFilterJSON: nil)

2022-09-26 10:49:54.420169+0100 MyApp Staging[3390:1147327] [StorageEngine] syncMutation(of:modelSchema:mutationType:predicate:syncEngine:completion:) successfully submitted to sync engine MutationEvent(id: "10B41BD9-1F22-44FD-85F0-A67755FEE516", modelId: "57C2339C-E35D-4730-B461-B50D4C250770", modelName: "MediaFile", json: "{ ...... redacted properties }", mutationType: "create", createdAt: Amplify.Temporal.DateTime(foundationDate: 2022-09-26 09:49:54 +0000, localTimezone: Optional(GMT (fixed))), version: nil, inProcess: true, graphQLFilterJSON: nil)

2022-09-26 10:49:54.420350+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."deleted" as "deleted", "root"."lastChangedAt" as "lastChangedAt",
  "root"."version" as "version"
from "MutationSyncMetadata" as "root"
where 1 = 1
  and "root"."id" = 'MediaFile|57C2339C-E35D-4730-B461-B50D4C250770'
limit 1 offset 0

2022-09-26 10:49:54.420419+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."deleted" as "deleted", "root"."lastChangedAt" as "lastChangedAt",
  "root"."version" as "version"
from "MutationSyncMetadata" as "root"
where 1 = 1
  and "root"."id" = 'MediaFile|57C2339C-E35D-4730-B461-B50D4C250770'
limit 1 offset 0
2022-09-26 10:49:54.420633+0100 MyApp Staging[3390:1147327] [StorageEngine] submitToSyncEngine(mutationEvent:syncEngine:completion:) Received successful completion

2022-09-26 10:49:54.423817+0100 MyApp Staging[3390:1147637] [SyncMutationToCloudOperation] sendMutation(describedBy:) sending mutation with sync data: GraphQLRequest<MutationSync<AnyModel>>(apiName: nil, document: "mutation CreateMediaFile($input: CreateMediaFileInput!) {\n  createMediaFile(input: $input) {\n    ...... redacted properties   }\n}", variables: Optional(["input": [ ...... redacted properties ]]), responseType: AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>, decodePath: Optional("createMediaFile"), options: Optional(Amplify.GraphQLRequest<AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>>.Options(pluginOptions: Optional(AWSPluginsCore.AWSPluginOptions(authType: nil)))))
2022-09-26 10:49:54.426035+0100 MyApp Staging[3390:1147637] [OutgoingMutationQueue] respond(to:): waitingForEventToProcess
2022-09-26 10:49:54.427316+0100 MyApp Staging[3390:1147637] [API] Starting mutation B68BC6EA-6D7E-4E7E-998D-9FE04AA2118B
2022-09-26 10:49:54.427427+0100 MyApp Staging[3390:1147637] [API] {
  "query" : "mutation CreateMediaFile($input: CreateMediaFileInput!) {\n  createMediaFile(input: $input) {...... redacted properties  }\n}",
  "variables" : {
    "input" : {
      ...... redacted properties
    }
  }
}

2022-09-26 10:49:54.441182+0100 MyApp Staging[3390:1147637] [API] Starting network task for mutation B68BC6EA-6D7E-4E7E-998D-9FE04AA2118B
2022-09-26 10:49:54.462750+0100 MyApp Staging[3390:1147327] [api] -[CIImage initWithCVPixelBuffer:options:] failed because the buffer is nil.

>>>>>>>>>>>> 🤔🤔🤔
2022-09-26 10:49:54.480206+0100 MyApp Staging[3390:1147637] BackgroundSession <53596A7F-E6DA-424C-BA70-FC0B4A3330F6> Failed to issue sandbox extension for file file:///private/var/mobile/Containers/Data/PluginKitPlugin/184D974A-464B-4448-825C-6D75999289CD/tmp/trim.EB7048E9-F63F-4101-AA24-40BB96DB2771.MOV, errno = [1: Operation not permitted]
>>>>>>>>>>>> 🤔🤔🤔

2022-09-26 10:49:54.980808+0100 MyApp Staging[3390:1147893] [SyncMutationToCloudOperation] GraphQL mutation operation received result: success(Swift.Result<AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>, Amplify.GraphQLResponseError<AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>>>.success(AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>(model: AWSPluginsCore.AnyModel(id: "57C2339C-E35D-4730-B461-B50D4C250770", instance: mymodule.MediaFile(id: "57C2339C-E35D-4730-B461-B50D4C250770", ...... redacted properties))))

2022-09-26 10:49:54.980970+0100 MyApp Staging[3390:1147893] [SyncMutationToCloudOperation] finish(result:)
2022-09-26 10:49:54.981293+0100 MyApp Staging[3390:1147647] [OutgoingMutationQueue] [SyncMutationToCloudOperation] mutationEvent finished: 10B41BD9-1F22-44FD-85F0-A67755FEE516; result: success(Swift.Result<AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>, Amplify.GraphQLResponseError<AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>>>.success(AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>(model: AWSPluginsCore.AnyModel(id: "57C2339C-E35D-4730-B461-B50D4C250770", instance: mymodule.MediaFile(id: "57C2339C-E35D-4730-B461-B50D4C250770", ...... redacted properties ), modelName: "MediaFile"), syncMetadata: AWSPluginsCore.MutationSyncMetadata(id: "MediaFile|57C2339C-E35D-4730-B461-B50D4C250770", deleted: false, lastChangedAt: 1664185794825, version: 1))))

2022-09-26 10:49:54.984325+0100 MyApp Staging[3390:1147647] [ReconcileAndLocalSaveOperation] New state: waiting
2022-09-26 10:49:54.984427+0100 MyApp Staging[3390:1147893] [ReconcileAndLocalSaveOperation] respond(to:): waiting
2022-09-26 10:49:54.984819+0100 MyApp Staging[3390:1147893] [ReconcileAndLocalSaveOperation] main()
2022-09-26 10:49:54.985095+0100 MyApp Staging[3390:1147647] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."createdAt" as "createdAt", "root"."graphQLFilterJSON" as "graphQLFilterJSON",
  "root"."inProcess" as "inProcess", "root"."json" as "json", "root"."modelId" as "modelId",
  "root"."modelName" as "modelName", "root"."mutationType" as "mutationType", "root"."version" as "version"
from "MutationEvent" as "root"
where 1 = 1
  and (
    (
      "root"."modelId" = '57C2339C-E35D-4730-B461-B50D4C250770'
    )
    and (
      "root"."inProcess" = 0
      or "root"."inProcess" is null
    )
  )
order by "root"."createdAt" asc
2022-09-26 10:49:54.985245+0100 MyApp Staging[3390:1147647] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."createdAt" as "createdAt", "root"."graphQLFilterJSON" as "graphQLFilterJSON",
  "root"."inProcess" as "inProcess", "root"."json" as "json", "root"."modelId" as "modelId",
  "root"."modelName" as "modelName", "root"."mutationType" as "mutationType", "root"."version" as "version"
from "MutationEvent" as "root"
where 1 = 1
  and (
    (
      "root"."modelId" = '57C2339C-E35D-4730-B461-B50D4C250770'
    )
    and (
      "root"."inProcess" = 0
      or "root"."inProcess" is null
    )
  )
order by "root"."createdAt" asc
2022-09-26 10:49:54.986743+0100 MyApp Staging[3390:1147637] [SQLiteStorageEngineAdapter] BEGIN DEFERRED TRANSACTION
2022-09-26 10:49:54.986945+0100 MyApp Staging[3390:1147637] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."createdAt" as "createdAt", "root"."graphQLFilterJSON" as "graphQLFilterJSON",
  "root"."inProcess" as "inProcess", "root"."json" as "json", "root"."modelId" as "modelId",
  "root"."modelName" as "modelName", "root"."mutationType" as "mutationType", "root"."version" as "version"
from "MutationEvent" as "root"
where 1 = 1
  and "root"."id" = '10B41BD9-1F22-44FD-85F0-A67755FEE516'
2022-09-26 10:49:54.987039+0100 MyApp Staging[3390:1147637] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."createdAt" as "createdAt", "root"."graphQLFilterJSON" as "graphQLFilterJSON",
  "root"."inProcess" as "inProcess", "root"."json" as "json", "root"."modelId" as "modelId",
  "root"."modelName" as "modelName", "root"."mutationType" as "mutationType", "root"."version" as "version"
from "MutationEvent" as "root"
where 1 = 1
  and "root"."id" = '10B41BD9-1F22-44FD-85F0-A67755FEE516'


>>>>>>>>>>>> many more mutations, syncs, etc... 


2022-09-26 10:49:55.258500+0100 MyApp Staging[3390:1147893] [StateMachine<State, Action>] Notifying: reconciled
2022-09-26 10:49:55.258711+0100 MyApp Staging[3390:1147893] [StateMachine<State, Action>] resolve(reconciling([AWSPluginsCore.MutationSync<AWSPluginsCore.AnyModel>(model: AWSPluginsCore.AnyModel(id: "57C2339C-E35D-4730-B461-B50D4C250770", instance: mymodule.MediaFile(id: "57C2339C-E35D-4730-B461-B50D4C250770", ...... redacted properties ), modelName: "MediaFile"), syncMetadata: AWSPluginsCore.MutationSyncMetadata(id: "MediaFile|57C2339C-E35D-4730-B461-B50D4C250770", deleted: false, lastChangedAt: 1664185794825, version: 1))]), reconciled) -> finished
2022-09-26 10:49:55.258760+0100 MyApp Staging[3390:1147893] [ReconcileAndLocalSaveOperation] New state: finished
2022-09-26 10:49:55.258848+0100 MyApp Staging[3390:1147893] [ReconcileAndLocalSaveOperation] respond(to:): finished


>>>>>>>>>>>> S3 uploadFile progress starts here 


[MyApp]: -> video upload progress 0.0
2022-09-26 10:49:56.442  ℹ️ INFO: -> video upload progress 0.0
2022-09-26 10:49:56.462  ℹ️ INFO: -> video upload completed ✓
[MyApp]: -> video upload completed ✓


>>>>>>>>>>>> S3 uploadFile progress finishes here 

2022-09-26 10:49:56.466975+0100 MyApp Staging[3390:1148091] [AWSDataStoreObserveQueryOperation<MediaFile>] Start ObserveQuery
2022-09-26 10:49:56.467351+0100 MyApp Staging[3390:1147647] [AWSDataStoreObserveQueryOperation<MediaFile>] Start ObserveQuery
2022-09-26 10:49:56.469066+0100 MyApp Staging[3390:1148091] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", ...... redacted properties
from "MediaFile" as "root"

...

2022-09-26 10:49:56.471025+0100 MyApp Staging[3390:1147647] [AWSDataStoreObserveQueryOperation<MediaFile>] Time to generate snapshot: 0.002259667 seconds
[MyApp]: -> MediaFile observeQuery last snapshot: UPLOADING nil true
2022-09-26 10:49:56.493207+0100 MyApp Staging[3390:1148091] [AWSDataStoreObserveQueryOperation<MediaFile>] Time to generate snapshot: 0.02443575 seconds
2022-09-26 10:49:56.493 com.amazonaws.AWSDataStoreObseverQueryOperation.serialQueue ℹ️ INFO: -> MediaFile observeQuery last snapshot: UPLOADING nil true

2022-09-26 10:49:56.493579+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."createdAt" as "createdAt", "root"."eventAt" as "eventAt",
  "root"."loggedAt" as "loggedAt",...... redacted properties
  "root"."updatedAt" as "updatedAt", ...... redacted properties
from "SideEffectEvent" as "root"
order by "root"."eventAt" asc
limit 1 offset 0
2022-09-26 10:49:56.493691+0100 MyApp Staging[3390:1147327] [SQLiteStorageEngineAdapter] select
  "root"."id" as "id", "root"."createdAt" as "createdAt", "root"."eventAt" as "eventAt",
  "root"."loggedAt" as "loggedAt", ...... redacted properties
  "root"."updatedAt" as "updatedAt", ...... redacted properties
from "SideEffectEvent" as "root"
order by "root"."eventAt" asc
limit 1 offset 0

>>>>>>>>>>>> loads more [SQLiteStorageEngineAdapter] select queries...

atierian · 2022-09-26T15:13:51Z

Thanks for the logs. We'll take a close look at this and get back to you here with any updates.

dsaliberti · 2022-09-27T12:16:40Z

@atierian Good news here 🎉
That line I marked as suspicious was the best clue I could get:

>>>>>>>>>>>> 🤔🤔🤔
2022-09-26 10:49:54.480206+0100 MyApp Staging[3390:1147637] BackgroundSession <53596A7F-E6DA-424C-BA70-FC0B4A3330F6> Failed to issue sandbox extension for file file:///private/var/mobile/Containers/Data/PluginKitPlugin/184D974A-464B-4448-825C-6D75999289CD/tmp/trim.EB7048E9-F63F-4101-AA24-40BB96DB2771.MOV, errno = [1: Operation not permitted]
>>>>>>>>>>>> 🤔🤔🤔

Basically I copied the video file into a folder within the app /documents and it works now!

I'd highlight from this:

S3 didn't "realise" the videos couldn't be uploaded and made it with 0 bytes
testing on Simulator always works as it's in the app's sandbox
no idea why with longer videos works

Thank you so much! Your request to mine my logs helped a lot! 👍

atierian · 2022-09-27T13:16:17Z

That's fantastic, thanks for letting us know!
Based on this, it looks like we could do a better job surfacing a helpful error message in these cases. I've opened aws-amplify/amplify-swift#2355 to track this and am closing this issue.

Thanks again!

atierian added bug Something isn't working s3 Issues related to S3 storage labels Sep 23, 2022

atierian mentioned this issue Sep 23, 2022

Property 'identifier' must be declared public because it matches a requirement in public protocol 'Model' aws-amplify/amplify-swift#2345

Closed

atierian mentioned this issue Sep 27, 2022

Storage.uploadFile inacurate error reporting by inaccessible files aws-amplify/amplify-swift#2355

Closed

atierian closed this as completed Sep 27, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[S3] `uploadFile` uploads successfully a `0` bytes length file only from device #4327

[S3] `uploadFile` uploads successfully a `0` bytes length file only from device #4327

dsaliberti commented Sep 23, 2022 •

edited

dsaliberti commented Sep 23, 2022

atierian commented Sep 23, 2022

dsaliberti commented Sep 23, 2022

dsaliberti commented Sep 23, 2022

dsaliberti commented Sep 23, 2022

atierian commented Sep 23, 2022

dsaliberti commented Sep 23, 2022 •

edited

dsaliberti commented Sep 26, 2022 •

edited by atierian

atierian commented Sep 26, 2022

dsaliberti commented Sep 27, 2022 •

edited

atierian commented Sep 27, 2022

[S3] uploadFile uploads successfully a 0 bytes length file only from device #4327

[S3] uploadFile uploads successfully a 0 bytes length file only from device #4327

Comments

dsaliberti commented Sep 23, 2022 • edited

dsaliberti commented Sep 23, 2022

atierian commented Sep 23, 2022

dsaliberti commented Sep 23, 2022

dsaliberti commented Sep 23, 2022

dsaliberti commented Sep 23, 2022

atierian commented Sep 23, 2022

dsaliberti commented Sep 23, 2022 • edited

dsaliberti commented Sep 26, 2022 • edited by atierian

atierian commented Sep 26, 2022

dsaliberti commented Sep 27, 2022 • edited

atierian commented Sep 27, 2022

[S3] `uploadFile` uploads successfully a `0` bytes length file only from device #4327

[S3] `uploadFile` uploads successfully a `0` bytes length file only from device #4327

dsaliberti commented Sep 23, 2022 •

edited

dsaliberti commented Sep 23, 2022 •

edited

dsaliberti commented Sep 26, 2022 •

edited by atierian

dsaliberti commented Sep 27, 2022 •

edited