Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

can not receive update Subscription event on 2.29.2 SDK version #3632

Closed
smediomike opened this issue Apr 25, 2024 · 32 comments
Closed

can not receive update Subscription event on 2.29.2 SDK version #3632

smediomike opened this issue Apr 25, 2024 · 32 comments
Assignees
Labels
bug Something isn't working datastore Issues related to the DataStore category

Comments

@smediomike
Copy link

Describe the bug

after upgrade to 2.92.2, iOS application can not receive update Subscription if application switch to background before. 2.17 SDK version is okay.

Steps To Reproduce

Steps to reproduce the behavior:
1, upgrade SDK to 2.29.2 
2, run application and go to background to take one picture
3, upload such picture to s3 storage, as this time, we can receive Subscription Add event, and datastore also can query such new record.
4, delete this item from web by grpahcGL
5, iOS application can not receive such Subscription event; on 2.17 SDK, we can receive such event. and also datastore can not sync such record till to re-start application.

possible root cause: 
our application go to background and then to foreground to upload and wait for update Subscription event. if we do not go to background and and do same steps, such issue do not happen.

Expected behavior

Application switch to background and then go to foreground, it should can receive update/delete Subscription event.

Amplify Framework Version

2.29.2

Amplify Categories

DataStore

Dependency manager

Swift PM

Swift version

5.0

CLI version

12.1.1

Xcode version

15.3

Relevant log output

Subscription received mutation: MutationEvent(id: "090D92A4-0B9F-40A4-AF48-E59D9E189784", modelId: "5A727AAF-B629-42FE-9242-70779BB7D5CD", modelName: "ImageVideo", json: "{\"album\":\"IMG_2367.PNG\",\"dateAdded\":\"2024-04-25T09:09:59.000Z\",\"dateBackup\":\"2024-04-25T09:14:02.818Z\",\"dateModified\":\"2024-04-25T09:10:00.094Z\",\"dateTaken\":\"2024-04-25T09:09:59.000Z\",\"duration\":0,\"hash\":\"8a55a76fd67c92b9f68846f6a7e3b190\",\"height\":2436,\"id\":\"5A727AAF-B629-42FE-9242-70779BB7D5CD\",\"isdeleted\":true,\"localPath\":\"IMG_2367.PNG\",\"mimeType\":\"image\\/png\",\"orientation\":1,\"roomId\":\"2\",\"s3Data\":\"2\\/image_video\\/8a55a76fd67c92b9f68846f6a7e3b190.PNG\",\"size\":\"6708712\",\"title\":\"IMG_2367.PNG\",\"tn1S3Data\":\"2\\/tn\\/image_video\\/8a55a76fd67c92b9f68846f6a7e3b190_web.jpg\",\"type\":2,\"updatedAt\":\"2024-04-25T09:14:02.818Z\",\"userId\":\"ap-northeast-1:e1e5ac7d-281f-4da8-bef9-cc71f42b17fc\",\"width\":1125}", mutationType: "update", createdAt: Amplify.Temporal.DateTime(foundationDate: 2024-04-25 09:14:03 +0000, timeZone: Optional(GMT (fixed))), version: Optional(2), inProcess: false, graphQLFilterJSON: nil)


now we can not receive such above Subscription if before application go to background.

Is this a regression?

Yes

Regression additional context

2.17 SDK do not happen such issue.

Platforms

iOS

OS Version

16.0~17.3

Device

iPhoneX/iPhone XR

Specific to simulators

No response

Additional context

No response

@lawmicha
Copy link
Member

Hi @smediomike, can you clarify with which API calls you making?

In step 3. upload such picture to s3 storage, how do you upload the S3 picture, through Amplify.Storage.upload? And where/how is the mutation sent for the client to receive the subscription event?

@lawmicha lawmicha added bug Something isn't working datastore Issues related to the DataStore category pending-triage Issue is pending triage labels Apr 25, 2024
@smediomike
Copy link
Author

smediomike commented Apr 26, 2024

Hi @lawmicha

  1. Amplify.Publisher.create(Amplify.DataStore.observe(model))
  2. Amplify.Storage.uploadFile or Amplify.Storage.uploadData
  3. try await Amplify.DataStore.save(model)
  4. Received changes.mutationType "create" ==> this is correct on 2.29.2 which same to 2.17
  5. delete such content by API on client or on web and mask datastore one fileld to "deleted" status by the below iOS code:
     let s3Dict = [ "roomId" : room,
                         "s3_key_filename" : fileName as Any,
                         "s3_key" : content.s3_data as Any] as [String : Any]
       jsonDict = [ "variables" : s3Dict,
                             "query" : "mutation Mark_delete_cloud_backup_ImageVideo($s3_key: String!) {\n  mark_delete_cloud_backup_ImageVideo(s3_key: $s3_key) {\n    userId\n    album\n    dateAdded\n    dateBackup\n    dateModified\n    dateTaken\n    deviceId\n    duration\n    hash\n    height\n    id\n    isdeleted\n    localPath\n    mimeType\n    orientation\n    roomId\n    s3Data\n    size\n    title\n    tn1S3Data\n    tn2S3Data\n    type\n    width\n    createdAt\n    updatedAt\n    _version\n    _deleted\n    _lastChangedAt\n  }\n}\n"
            ] as [String : Any] 
var jsonData : Data? = nil;
        do {
            jsonData = try JSONSerialization.data(withJSONObject: jsonDict as Any, options: .prettyPrinted)
        }catch {
            
        }
            
        let request = RESTRequest(apiName:"dataStoreApi",path: nil, body: jsonData)
let data = try await Amplify.API.post(request: request)
            let str = String(decoding: data, as: UTF8.self)
            print("mark delete Success: \(str)")
  1. we can see this content is be deleted, but we can not receive changes.mutationType "update" event on 2.29.2, but 2.17 can receive

Note: this issue only happen iOS application go to background and then back to foreground. if application always keep in foreground, this issue will not happen.

I will check more whether we need to step #1 again if application go to background before. thanks for your help!

@smediomike
Copy link
Author

Hi @lawmicha

add more information, I cancel old Subscription and add new Subscription after go to foreground, this issue still happen. BTW, once happen this issue, this "update" record will not be sync to local datastore till to re-start application.

@smediomike
Copy link
Author

Hi @lawmicha
add more information, I rollback SDK version to 2.26.1; this issue will not happen.

@lawmicha lawmicha self-assigned this Apr 30, 2024
@ruisebas
Copy link
Member

ruisebas commented May 6, 2024

Hi @smediomike,

We've recently addressed an issue that was causing network-related problems in the latest version 2.33.3.
Would you mind please upgrading to this version and verifying if it also addresses your issue?

Thanks!

@umamario
Copy link

umamario commented May 30, 2024

Hi @ruisebas

We have also being struggling with this same issue with the latest version 2.34.2 and with 2.33.3.
It does work with 2.26.1.

@5d
Copy link
Member

5d commented May 30, 2024

Hi @umamario @smediomike
Could you please share the verbose logs with us when the issue occurs?

@thisisabhash thisisabhash added pending-community-response Issue is pending response from the issue requestor and removed pending-triage Issue is pending triage labels Jun 14, 2024
@lawmicha
Copy link
Member

#3734 has been released in https://github.com/aws-amplify/amplify-swift/releases/tag/2.35.1 Please let us know if you are still experiencing any issues from 2.35.1 and newer

@github-actions github-actions bot removed the pending-community-response Issue is pending response from the issue requestor label Jun 17, 2024
@smediomike
Copy link
Author

I used 2.35.1 version to re-test, such issue still happen. and client side do not show any AWS SDK log at that time.

@tobias-feldmann
Copy link

Same problem with 2.35.3.
After the app was in the background and becomes active again, we no longer receive Datastore updates.
The following error is in the log:

024-06-20 20:16:00.236994+0200 BeTidy[2428:253982] [websocket] Read completed with an error Software caused connection abort 2024-06-20 20:16:00.237163+0200 BeTidy[2428:253982] Task <1B0C1B7D-FC87-4100-AA1B-A297EF4A314F>.<1> finished with error [53] Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=( "LocalWebSocketTask <1B0C1B7D-FC87-4100-AA1B-A297EF4A314F>.<1>" ), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask <1B0C1B7D-FC87-4100-AA1B-A297EF4A314F>.<1>} 2024-06-20 20:16:00.237395+0200 BeTidy[2428:253802] Task <F3D85823-0F55-4C76-9207-9597C603E490>.<1> finished with error [53] Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=( "LocalWebSocketTask <F3D85823-0F55-4C76-9207-9597C603E490>.<1>" ), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask <F3D85823-0F55-4C76-9207-9597C603E490>.<1>} 2024-06-20 20:16:00.237466+0200 BeTidy[2428:253801] [connection] nw_flow_add_write_request [C2.1 3.122.42.201:443 failed channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, ipv6, dns)] cannot accept write requests 2024-06-20 20:16:00.237582+0200 BeTidy[2428:253801] [connection] nw_write_request_report [C2] Send failed with error "Socket is not connected" 2024-06-20 20:16:00.238292+0200 BeTidy[2428:253801] Connection 3: received failure notification 2024-06-20 20:16:00.238347+0200 BeTidy[2428:253801] [connection] nw_flow_add_write_request [C3.1 3.124.41.201:443 failed channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, ipv6, dns)] cannot accept write requests 2024-06-20 20:16:00.238382+0200 BeTidy[2428:253801] [connection] nw_write_request_report [C3] Send failed with error "Socket is not connected"

@5d
Copy link
Member

5d commented Jun 20, 2024

Hi @smediomike @tobias-feldmann ,

In the described test scenario, how long does the app remain in background mode before becoming active again?

@tobias-feldmann
Copy link

tobias-feldmann commented Jun 20, 2024

Hi @5d
Only very short in the background and immediately back again. So maybe 2 seconds.
I then have to close the app completely and restart it so that the sync starts again.

When the app is back in the foreground, I get the error from above.

@5d
Copy link
Member

5d commented Jun 20, 2024

Hi @tobias-feldmann ,

Thanks for the information. By the way, are you testing on a real device? What is the internet environment like? Is it connected to both Wi-Fi and cellular networks?

@tobias-feldmann
Copy link

You are welcome @5d
Yes, I have tested on a real device with only wifi connected.

@5d
Copy link
Member

5d commented Jun 20, 2024

Hi @tobias-feldmann ,

I was not able to replicate the ECONNABORTED error as you did. Could you share the code snippet showing how you're using the datastore?
Specifically, I noticed the log message
[websocket] Read completed with an error: Software caused connection abort 2024-06-20 20:16:00.237163+0200 BeTidy[2428:253982] Task <1B0C1B7D-FC87-4100-AA1B-A297EF4A314F>.<1> finished with error [53] Error Domain=kNWErrorDomainPOSIX Code=53.
Is this an error you log in your app, or is it from the Apple system?

@tobias-feldmann
Copy link

@5d
I have now run several tests.
It works in the simulator. Tested on iOS 15.5 and 17.4.
On real devices it also works on an iPhone 12mini with iOS 17.4.1. Tested with Wifi and mobile connection.
I only have the problem on an iPhone SE with iOS 15.6.1. There is no SIM in the iPhone SE, but in the iPhone 12mini.

Looks like the error is coming from the AppSyncRealTimeClient:

2024-06-21 08:56:02.982986+0200 BeTidy[2914:295927] [APIAppSyncRealTimeClient] [AppSyncRealTimeClient] Received websocket event error(Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalWebSocketTask .<1>"
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask .<1>})

Several selects are made via the DataStore beforehand, then the errors occur.
Here is the complete log with loglevel verbose:

2024-06-21 08:56:02.965304+0200 BeTidy[2914:296133] [DataStoreSQLiteStorageEngineAdapter] select
"root"."id" as "id", "root"."afterImage" as "afterImage", "root"."beforeImage" as "beforeImage",
"root"."createdAt" as "createdAt", "root"."creator" as "creator", "root"."identityId" as "identityId",
"root"."roomId" as "roomId", "root"."startDate" as "startDate", "root"."templateId" as "templateId",
"root"."title" as "title", "root"."type" as "type", "root"."updatedAt" as "updatedAt"
from "UserProject" as "root"
2024-06-21 08:56:02.971871+0200 BeTidy[2914:296018] [connection] nw_read_request_report [C6] Receive failed with error "Software caused connection abort"
2024-06-21 08:56:02.972507+0200 BeTidy[2914:296018] [connection] nw_read_request_report [C2] Receive failed with error "Software caused connection abort"
2024-06-21 08:56:02.972642+0200 BeTidy[2914:296018] [connection] nw_read_request_report [C4] Receive failed with error "Software caused connection abort"
2024-06-21 08:56:02.973626+0200 BeTidy[2914:296133] [DataStoreSQLiteStorageEngineAdapter] select
"root"."id" as "id", "root"."active" as "active", "root"."assigned" as "assigned",
"root"."createdAt" as "createdAt", "root"."creator" as "creator", "root"."days" as "days",
"root"."description" as "description", "root"."effort" as "effort", "root"."finishedDate" as "finishedDate",
"root"."identityId" as "identityId", "root"."important" as "important", "root"."intervalCount" as "intervalCount",
"root"."intervalUnit" as "intervalUnit", "root"."lastHistoryId" as "lastHistoryId", "root"."lastSkipDate" as "lastSkipDate",
"root"."lastTodoDate" as "lastTodoDate", "root"."projectId" as "projectId", "root"."roomId" as "roomId",
"root"."templateId" as "templateId", "root"."title" as "title", "root"."todoDate" as "todoDate",
"root"."type" as "type", "root"."updatedAt" as "updatedAt"
from "UserTask" as "root"
where 1 = 1
and "root"."projectId" = '6AB54C74-9D23-45A7-9AF8-61D2A0C57FBC'
2024-06-21 08:56:02.973665+0200 BeTidy[2914:296018] [connection] nw_read_request_report [C5] Receive failed with error "Software caused connection abort"
2024-06-21 08:56:02.981355+0200 BeTidy[2914:295927] [websocket] Read completed with an error Software caused connection abort
2024-06-21 08:56:02.981992+0200 BeTidy[2914:295927] Task .<1> finished with error [53] Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalWebSocketTask .<1>"
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask .<1>}
2024-06-21 08:56:02.982659+0200 BeTidy[2914:295927] [WebSocketClient] [WebSocketClient] URLSession didCompleteWithError: Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalWebSocketTask .<1>"
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask .<1>})
2024-06-21 08:56:02.982986+0200 BeTidy[2914:295927] [APIAppSyncRealTimeClient] [AppSyncRealTimeClient] Received websocket event error(Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalWebSocketTask .<1>"
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask .<1>})
2024-06-21 08:56:02.983016+0200 BeTidy[2914:295927] [APIAppSyncRealTimeClient] [AppSyncRealTimeClient] WebSocket error event: Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=(
"LocalWebSocketTask .<1>"
), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask .<1>}
2024-06-21 08:56:02.983310+0200 BeTidy[2914:296018] Connection 4: received failure notification
2024-06-21 08:56:02.983364+0200 BeTidy[2914:296018] [connection] nw_flow_add_write_request [C4.5 3.125.44.201:443 failed channel-flow (satisfied (Path is satisfied), viable, interface: en0, ipv4, ipv6, dns)] cannot accept write requests
2024-06-21 08:56:02.983396+0200 BeTidy[2914:296018] [connection] nw_write_request_report [C4] Send failed with error "Socket is not connected"
2024-06-21 08:56:02.984191+0200 BeTidy[2914:295930] [WebSocketClient] [WebSocketClient] read message failed with connection state NSURLSessionTaskState(rawValue: 3), error Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort}
2024-06-21 08:56:02.984223+0200 BeTidy[2914:295930] [WebSocketClient] [WebSocketClient] WebSocket connection state is NSURLSessionTaskState(rawValue: 3). Failed to read websocket message

@5d
Copy link
Member

5d commented Jun 22, 2024

Hi @tobias-feldmann ,

Thank you for the information. I tried to reproduce the issue using an iOS 15.6 simulator but had no success. We currently do not have a test device running iOS 15. We will contact other teams to see if they have one available.

Regarding the Domain=kNWErrorDomainPOSIX Code=53 error, we capture it to mark the network status as offline and reconnect the device once the network is back online. Our network status monitoring relies on NWPathMonitor. There could be issues with this on an actual device. I have implemented a backup method that regularly pings 1.1.1.1 to check network availability. Could you please test this and see if it resolves the issue? You can find the changes on the 5d/network-availability-check branch.

@tobias-feldmann
Copy link

Hi @5d
I have tested it with this branch. But unfortunately no change, same error.

@tobias-feldmann
Copy link

tobias-feldmann commented Jun 23, 2024

@5d
The problem is totally strange. The problem also exists with the current iOS 17.5.1 but only on real devices. And only if the app was not started via xcode.
It looks as if the connection via xcode keeps the socket connections active. If you do not start the app via xcode, the problem occurs immediately when you put the app in the background and then back again. This should therefore affect all devices.

Do you know which version I could go back to where the problem does not exist? Because this function is critical for our app and I need to provide a fix.

@tobias-feldmann
Copy link

I have now tested different amplify versions with 2.35.0, 2.33.4, 2.33.2 it does not work. But it works with 2.28.0. Is probably related to the changes in 2.29.1

@harsh62
Copy link
Member

harsh62 commented Jun 25, 2024

@tobias-feldmann Thanks for providing all that valuable information. It could be probably 2.29.1. Our team will investigate and provide an update soon.

@5d
Copy link
Member

5d commented Jul 2, 2024

Hi @tobias-feldmann ,

Thanks for the information. I was able to reproduce the issue with Xcode disconnected. I'm noticing that when the app transitions to the background, the WebSocket connection encounters a system network abort error. This error is originating from the iOS system through URLSession delegate methods, and we propagate these errors downstream. However, these errors do not terminate the data stream on the Amplify observe API or the subscription API. I can see the reconnection attempts in the logs, and data updates are received from other devices continue afterward.

Are you expecting not to receive the error messages? Or is the issue that data is not received once the app returns to the foreground?

Here are my logs:

CloudWatch Logs Insights
region: us-east-1
log-group-names: /aws/amplify/testing-1
start-time: -3600s
end-time: 0s
query-string:

fields @timestamp, @message, @logStream, @log
| filter @message like 'WebSocketClient'
| sort @timestamp desc
| limit 10000

@timestamp @message @logstream @log
2024-07-02 18:32:55.136 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"type":"ka"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:31:55.378 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"type":"ka"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:30:55.183 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"type":"ka"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:30:40.097 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"D323ACE5-03CA-49B2-9B69-3F4A520D59DC","type":"data","payload":{"data":{"onDeleteComment":{"id":"E2F06D24-63D9-46D4-A161-EAFB18E22F08","content":"Content1 2024-07-02 18:30:37 +0000","createdAt":"2024-07-02T18:30:38.416Z","updatedAt":"2024-07-02T18:30:38.416Z","post":{"id":"017953C0-9490-48B4-8836-F827F35CF679","createdAt":"2024-07-02T18:30:37.915Z","title":"post-2024-07-02 18:30:37 +0000","updatedAt":"2024-07-02T18:30:37.915Z","__typename":"Post","_version":1,"_deleted":null,"_lastChangedAt":1719945037948},"__typename":"Comment","_version":2,"_deleted":true,"_lastChangedAt":1719945039931}}}}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:30:38.703 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"4803EEFB-D97F-4CCC-8C52-721851E1401B","type":"data","payload":{"data":{"onCreateComment":{"id":"E2F06D24-63D9-46D4-A161-EAFB18E22F08","content":"Content1 2024-07-02 18:30:37 +0000","createdAt":"2024-07-02T18:30:38.416Z","updatedAt":"2024-07-02T18:30:38.416Z","post":{"id":"017953C0-9490-48B4-8836-F827F35CF679","createdAt":"2024-07-02T18:30:37.915Z","title":"post-2024-07-02 18:30:37 +0000","updatedAt":"2024-07-02T18:30:37.915Z","__typename":"Post","_version":1,"_deleted":null,"_lastChangedAt":1719945037948},"__typename":"Comment","_version":1,"_deleted":null,"_lastChangedAt":1719945038450}}}}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:30:38.223 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"B722EEF5-257D-40C8-8424-D1DBCCFE260C","type":"data","payload":{"data":{"onCreatePost":{"id":"017953C0-9490-48B4-8836-F827F35CF679","createdAt":"2024-07-02T18:30:37.915Z","title":"post-2024-07-02 18:30:37 +0000","updatedAt":"2024-07-02T18:30:37.915Z","blog":{"id":"9ddae298-8aa5-421a-b0ea-e3e785dbdd34","createdAt":"2024-01-16T20:50:32.406Z","name":"41137C56-A4C1-4B10-B0B0-C41D58C5A269","updatedAt":"2024-07-02T17:59:57.643Z","__typename":"Blog","_version":4,"_deleted":null,"_lastChangedAt":1719943197679},"__typename":"Post","_version":1,"_deleted":null,"_lastChangedAt":1719945037948}}}}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:29:55.211 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"type":"ka"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:28:55.143 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"type":"ka"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:27:55.141 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"type":"ka"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.515 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"8629CBD7-15CD-45A7-A460-CCCF38DB5AEB","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.504 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"43710695-E7CC-451F-8396-2D2C7325F530","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.498 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"81841FE0-4D45-4BD0-AFF4-6A5DD19EDC30","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.493 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"BE6CA73D-635B-4201-BD52-E203C660447C","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.492 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"5795594A-BBF3-4330-BAF6-CCEA03144053","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.488 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"7EBC932B-E318-4EC8-A624-E2733D874DCF","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.488 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"4803EEFB-D97F-4CCC-8C52-721851E1401B","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.486 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"D323ACE5-03CA-49B2-9B69-3F4A520D59DC","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:55.483 DEBUG/WebSocketClient: [WebSocketClient] WebSocket received message: string("{"id":"B722EEF5-257D-40C8-8424-D1DBCCFE260C","type":"start_ack"}") 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.582 DEBUG/WebSocketClient: [WebSocketClient] NetworkMonitor - Device back online 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.582 DEBUG/WebSocketClient: [WebSocketClient] Creating new connection and starting read 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.381 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"id":"5795594A-BBF3-4330-BAF6-CCEA03144053","type":"stop"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.381 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"type":"stop","id":"7EBC932B-E318-4EC8-A624-E2733D874DCF"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"type":"stop","id":"BE6CA73D-635B-4201-BD52-E203C660447C"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"id":"D323ACE5-03CA-49B2-9B69-3F4A520D59DC","type":"stop"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"type":"stop","id":"4803EEFB-D97F-4CCC-8C52-721851E1401B"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"id":"43710695-E7CC-451F-8396-2D2C7325F530","type":"stop"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"type":"stop","id":"81841FE0-4D45-4BD0-AFF4-6A5DD19EDC30"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"id":"8629CBD7-15CD-45A7-A460-CCCF38DB5AEB","type":"stop"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.380 DEBUG/WebSocketClient: [WebSocketClient] WebSocket write message string: {"id":"B722EEF5-257D-40C8-8424-D1DBCCFE260C","type":"stop"} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.377 DEBUG/WebSocketClient: [WebSocketClient] read message failed with connection state NSURLSessionTaskState(rawValue: 3), error Error Domain=NSPOSIXErrorDomain Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort} 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.377 DEBUG/WebSocketClient: [WebSocketClient] WebSocket connection state is NSURLSessionTaskState(rawValue: 3). Failed to read websocket message 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.377 DEBUG/WebSocketClient: [WebSocketClient] URLSession didCompleteWithError: Error Domain=NSPOSIXErrorDomain Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort, _NSURLErrorRelatedURLSessionTaskErrorKey=( "LocalWebSocketTask <4CC7B011-9FB5-46BA-8121-353E19DC5C58>.<1>" ), _NSURLErrorFailingURLSessionTaskErrorKey=LocalWebSocketTask <4CC7B011-9FB5-46BA-8121-353E19DC5C58>.<1>}) 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.377 DEBUG/WebSocketClient: [WebSocketClient] NetworkMonitor - Device went offline 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1
2024-07-02 18:26:54.377 DEBUG/API: <AWSAPIPlugin.AWSAPIPlugin: 0x303ea43c0>: [AppSyncRealTimeClient] Received websocket event error(AWSPluginsCore.WebSocketClient.Error.connectionLost) 15F4AEA5-59A8-49F2-9F95-4E198E120EF9.d4686448-d071-7030-f696-30e8be59a409 123456789012:/aws/amplify/testing-1

@tobias-feldmann
Copy link

Hi @5d
The error messages are not a problem. But the user does not get any updated data until he closes the app completely and restarts it.

@5d
Copy link
Member

5d commented Jul 2, 2024

Hi @tobias-feldmann ,

The version 2.29.1 contains switching from the third-party dependency library Starscream to Apple's native WebSocket solution, URLSessionWebSocketTask. This change may have introduced some behavioral differences in handling networking errors during background and foreground operations.

I have done some additional testing with the device disconnected from Xcode. It seems that some updates made while the device is in background mode are not received. However, once the device returns to the foreground, all subsequent updates are received. I am currently testing with the branch 5d/network-availability-check.

Are you experiencing the same behavior, or are you finding that updates are not received regardless of whether they are made while the device is in the background or when it returns to the foreground?

@tobias-feldmann
Copy link

I have tested the following case, which is very important for our app:

Device A loads data from the DataStore and displays it. The app goes then in the background.
Device B opens the app and updates the data that is also used by device A.
Device A opens the app again. The app makes a DataStore Select for the data. However, the DataStore still provides the old data and does not update. The data is only updated when the app is completely closed and restarted.

@harsh62
Copy link
Member

harsh62 commented Jul 11, 2024

@tobias-feldmann Thanks for the information, is this something that you tested on Di's branch 5d/network-availability-check?

@tobias-feldmann
Copy link

Hi @harsh62
yes, I also tested it with the 5d/network-availability-check branch but unfortunately it doesn't work.

@harsh62
Copy link
Member

harsh62 commented Jul 16, 2024

@tobias-feldmann Thanks for clarifying. Our team will further investigate and provide an update as soon as we have one.

@5d
Copy link
Member

5d commented Jul 31, 2024

Hi @tobias-feldmann ,

I've updated the branch 5d/network-availability-check to restart the sync engine when the network is aborted. I tested it with a simple app, and it worked fine. Could you try it with your project to confirm if it mitigates the issue?

@tobias-feldmann
Copy link

Hi @5d

I have just tested it.
Works great now. Thank you very much. :)

I had the following errors in the log. If it is relevant for you:

Task <6CA6F182-7C37-4094-BA24-3BD37A7938AF>.<45> finished with error [-1001] Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2102, NSUnderlyingError=0x3012c2130 {Error Domain=kCFErrorDomainCFNetwork Code=-1001 "(null)" UserInfo={_kCFStreamErrorCodeKey=-2102, _kCFStreamErrorDomainKey=4}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <6CA6F182-7C37-4094-BA24-3BD37A7938AF>.<45>, _NSURLErrorRelatedURLSessionTaskErrorKey=("LocalDataTask <6CA6F182-7C37-4094-BA24-3BD37A7938AF>.<45>"), NSLocalizedDescription=The request timed out., NSErrorFailingURLStringKey=https://one.one.one.one/, NSErrorFailingURLKey=https://one.one.one.one/, _kCFStreamErrorDomainKey=4}

[InitializeSubscription.3] AWSModelReconciliationQueue receiveCompletion: error: DataStoreError: WebSocketClient connection aborted Recovery suggestion: WebSocketClient connection aborted
Caused by: APIError: WebSocketClient connection aborted
Recovery suggestion: WebSocketClient connection aborted
Caused by: connectionCancelled

@5d
Copy link
Member

5d commented Aug 6, 2024

Hi @tobias-feldmann ,

With the 5d/network-availability-check branch, those error logs are expected. The first "request timed out" error for one.one.one.one was intentionally added to test if the NWPathMonitor is functioning correctly. This will be removed before we create the PR to the main branch.

The second error is necessary to notify the sync engine that the network has been interrupted and needs to restart.

I am currently preparing the integration test and will create the PR for this. I will inform you once the patch is released.

@5d
Copy link
Member

5d commented Aug 13, 2024

Hi @tobias-feldmann ,

The fix patch has been released in version 2.37.0. I'll go ahead and close this issue for now, but feel free to reopen it if the problem persists.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working datastore Issues related to the DataStore category
Projects
None yet
Development

No branches or pull requests

8 participants