-
Notifications
You must be signed in to change notification settings - Fork 116
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
Item entered offline refuses to sync to backend #823
Comments
2020-09-14 08:03:34.224 5054-5054/? I/amplify_androi: Not late-enabling -Xcheck:jni (already on)
2020-09-14 08:03:34.267 5054-5054/? I/amplify_androi: Unquickening 12 vdex files!
2020-09-14 08:03:34.268 5054-5054/? W/amplify_androi: Unexpected CPU variant for X86 using defaults: x86
2020-09-14 08:03:34.314 5054-5054/com.example.amplify_android I/amplify_androi: The ClassLoaderContext is a special shared library.
2020-09-14 08:03:34.331 5054-5054/com.example.amplify_android D/NetworkSecurityConfig: No Network Security Config specified, using platform default
2020-09-14 08:03:34.332 5054-5054/com.example.amplify_android D/NetworkSecurityConfig: No Network Security Config specified, using platform default
2020-09-14 08:03:34.402 5054-5054/com.example.amplify_android I/amplify: Initialized Amplify
2020-09-14 08:03:34.464 5054-5086/com.example.amplify_android D/libEGL: loaded /vendor/lib/egl/libEGL_emulation.so
2020-09-14 08:03:34.465 5054-5086/com.example.amplify_android D/libEGL: loaded /vendor/lib/egl/libGLESv1_CM_emulation.so
2020-09-14 08:03:34.469 5054-5086/com.example.amplify_android D/libEGL: loaded /vendor/lib/egl/libGLESv2_emulation.so
2020-09-14 08:03:34.506 5054-5054/com.example.amplify_android W/amplify_androi: Accessing hidden method Landroid/view/View;->computeFitSystemWindows(Landroid/graphics/Rect;Landroid/graphics/Rect;)Z (greylist, reflection, allowed)
2020-09-14 08:03:34.506 5054-5054/com.example.amplify_android W/amplify_androi: Accessing hidden method Landroid/view/ViewGroup;->makeOptionalFitsSystemWindows()V (greylist, reflection, allowed)
2020-09-14 08:03:34.537 5054-5080/com.example.amplify_android I/amplify:aws-datastore: DataStore orchestrator transitioning states. Current mode = STOPPED, target mode = SYNC_VIA_API.
2020-09-14 08:03:34.538 5054-5080/com.example.amplify_android I/amplify:aws-datastore: Starting to observe local storage changes.
2020-09-14 08:03:34.545 5054-5083/com.example.amplify_android I/amplify:aws-datastore: Now observing local storage. Local changes will be enqueued to mutation outbox.
2020-09-14 08:03:34.550 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Starting API synchronization mode.
2020-09-14 08:03:34.608 5054-5097/com.example.amplify_android W/amplify:aws-api: Websocket connection failed.
2020-09-14 08:03:34.657 5054-5084/com.example.amplify_android D/HostConnection: HostConnection::get() New Host Connection established 0xf63d5a30, tid 5084
2020-09-14 08:03:34.668 5054-5084/com.example.amplify_android D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_vulkan ANDROID_EMU_deferred_vulkan_commands ANDROID_EMU_vulkan_null_optional_strings ANDROID_EMU_vulkan_create_resources_with_requirements ANDROID_EMU_YUV_Cache ANDROID_EMU_async_unmap_buffer ANDROID_EMU_vulkan_ignored_handles ANDROID_EMU_vulkan_free_memory_sync ANDROID_EMU_vulkan_shader_float16_int8 ANDROID_EMU_vulkan_async_queue_submit GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_gles_max_version_2
2020-09-14 08:03:34.673 5054-5084/com.example.amplify_android W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
2020-09-14 08:03:34.686 5054-5084/com.example.amplify_android D/EGL_emulation: eglCreateContext: 0xf61663b0: maj 2 min 0 rcv 2
2020-09-14 08:03:34.718 5054-5084/com.example.amplify_android D/EGL_emulation: eglMakeCurrent: 0xf61663b0: ver 2 0 (tinfo 0xf6536d70) (first time)
2020-09-14 08:03:34.767 5054-5084/com.example.amplify_android I/Gralloc4: mapper 4.x is not supported
2020-09-14 08:03:34.768 5054-5084/com.example.amplify_android D/HostConnection: createUnique: call
2020-09-14 08:03:34.768 5054-5084/com.example.amplify_android D/HostConnection: HostConnection::get() New Host Connection established 0xf63d5c10, tid 5084
2020-09-14 08:03:34.768 5054-5084/com.example.amplify_android D/goldfish-address-space: allocate: Ask for block of size 0x100
2020-09-14 08:03:34.768 5054-5084/com.example.amplify_android D/goldfish-address-space: allocate: ioctl allocate returned offset 0x3f6599000 size 0x2000
2020-09-14 08:03:34.772 5054-5084/com.example.amplify_android D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_vulkan ANDROID_EMU_deferred_vulkan_commands ANDROID_EMU_vulkan_null_optional_strings ANDROID_EMU_vulkan_create_resources_with_requirements ANDROID_EMU_YUV_Cache ANDROID_EMU_async_unmap_buffer ANDROID_EMU_vulkan_ignored_handles ANDROID_EMU_vulkan_free_memory_sync ANDROID_EMU_vulkan_shader_float16_int8 ANDROID_EMU_vulkan_async_queue_submit GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_gles_max_version_2
2020-09-14 08:03:36.066 5054-5054/com.example.amplify_android I/amplify:aws-datastore: DataStore orchestrator transitioning states. Current mode = LOCAL_ONLY, target mode = SYNC_VIA_API.
2020-09-14 08:03:36.072 5054-5083/com.example.amplify_android I/amplify: retrieved todos
2020-09-14 08:03:36.073 5054-5083/com.example.amplify_android I/amplify: Todo {id=05eec008-eb4f-412e-8b41-0d096f2b36f3, name=test, description=test}
2020-09-14 08:03:36.073 5054-5083/com.example.amplify_android I/amplify: Todo {id=4af78b54-2fb8-4abe-8512-e2491a0f65d9, name=test2, description=test2}
2020-09-14 08:03:42.617 5054-5054/com.example.amplify_android I/amplify:aws-datastore: DataStore orchestrator transitioning states. Current mode = LOCAL_ONLY, target mode = SYNC_VIA_API.
2020-09-14 08:03:42.622 5054-5083/com.example.amplify_android I/amplify: retrieved todos
2020-09-14 08:03:42.622 5054-5083/com.example.amplify_android I/amplify: Todo {id=05eec008-eb4f-412e-8b41-0d096f2b36f3, name=test, description=test}
2020-09-14 08:03:42.622 5054-5083/com.example.amplify_android I/amplify: Todo {id=4af78b54-2fb8-4abe-8512-e2491a0f65d9, name=test2, description=test2}
2020-09-14 08:03:44.567 5054-5088/com.example.amplify_android W/amplify:aws-datastore: Subscription processor failed to start within the expected timeout.
2020-09-14 08:03:44.615 5054-5095/com.example.amplify_android W/amplify:aws-datastore: An error occurred on the remote Todo subscription for model ON_CREATE.
AmplifyException {message=Error during subscription., cause=AmplifyException {message=Subscription not acknowledged., cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}
at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$subscription$3(AppSyncClient.java:293)
at com.amplifyframework.datastore.appsync.-$$Lambda$AppSyncClient$8gXTT9bgLZGP51blif6hkh7EwIc.accept(Unknown Source:4)
at com.amplifyframework.api.aws.SubscriptionOperation.lambda$null$1$SubscriptionOperation(SubscriptionOperation.java:94)
at com.amplifyframework.api.aws.-$$Lambda$SubscriptionOperation$EfR-sAOj2xzA_-vAoxWBdb2iFk8.accept(Unknown Source:4)
at com.amplifyframework.api.aws.SubscriptionEndpoint$Subscription.dispatchError(SubscriptionEndpoint.java:377)
at com.amplifyframework.api.aws.SubscriptionEndpoint$Subscription.awaitSubscriptionReady(SubscriptionEndpoint.java:329)
at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:161)
at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$SubscriptionOperation(SubscriptionOperation.java:83)
at com.amplifyframework.api.aws.-$$Lambda$SubscriptionOperation$Uz-v98-sFPcWrrCLK25EF8LKbXo.run(Unknown Source:2)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:923)
Caused by: AmplifyException {message=Subscription not acknowledged., cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
at com.amplifyframework.api.aws.SubscriptionEndpoint$Subscription.awaitSubscriptionReady(SubscriptionEndpoint.java:329)
at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:161)
at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$SubscriptionOperation(SubscriptionOperation.java:83)
at com.amplifyframework.api.aws.-$$Lambda$SubscriptionOperation$Uz-v98-sFPcWrrCLK25EF8LKbXo.run(Unknown Source:2)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:923)
2020-09-14 08:03:44.616 5054-5096/com.example.amplify_android W/amplify_androi: Long monitor contention with owner pool-2-thread-2 (5095) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=0 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 10.020s
2020-09-14 08:03:44.623 5054-5096/com.example.amplify_android W/amplify:aws-api: Connection attempt interrupted.
2020-09-14 08:03:44.625 5054-5094/com.example.amplify_android W/amplify_androi: Long monitor contention with owner pool-2-thread-2 (5095) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=1 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 10.023s
2020-09-14 08:03:44.629 5054-5094/com.example.amplify_android W/amplify:aws-api: Connection attempt interrupted.
2020-09-14 08:03:45.261 5054-5326/com.example.amplify_android I/amplify:aws-datastore: Successfully sync'd down model state from cloud.
2020-09-14 08:03:45.262 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Starting processing subscription data buffer.
2020-09-14 08:03:45.262 5054-5088/com.example.amplify_android W/amplify:aws-datastore: Reading subscriptions buffer has failed.
AmplifyException {message=Error during subscription., cause=AmplifyException {message=Subscription not acknowledged., cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}
at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$subscription$3(AppSyncClient.java:293)
at com.amplifyframework.datastore.appsync.-$$Lambda$AppSyncClient$8gXTT9bgLZGP51blif6hkh7EwIc.accept(Unknown Source:4)
at com.amplifyframework.api.aws.SubscriptionOperation.lambda$null$1$SubscriptionOperation(SubscriptionOperation.java:94)
at com.amplifyframework.api.aws.-$$Lambda$SubscriptionOperation$EfR-sAOj2xzA_-vAoxWBdb2iFk8.accept(Unknown Source:4)
at com.amplifyframework.api.aws.SubscriptionEndpoint$Subscription.dispatchError(SubscriptionEndpoint.java:377)
at com.amplifyframework.api.aws.SubscriptionEndpoint$Subscription.awaitSubscriptionReady(SubscriptionEndpoint.java:329)
at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:161)
at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$SubscriptionOperation(SubscriptionOperation.java:83)
at com.amplifyframework.api.aws.-$$Lambda$SubscriptionOperation$Uz-v98-sFPcWrrCLK25EF8LKbXo.run(Unknown Source:2)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:923)
Caused by: AmplifyException {message=Subscription not acknowledged., cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
at com.amplifyframework.api.aws.SubscriptionEndpoint$Subscription.awaitSubscriptionReady(SubscriptionEndpoint.java:329)
at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:161)
at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$SubscriptionOperation(SubscriptionOperation.java:83)
at com.amplifyframework.api.aws.-$$Lambda$SubscriptionOperation$Uz-v98-sFPcWrrCLK25EF8LKbXo.run(Unknown Source:2)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
at java.lang.Thread.run(Thread.java:923)
2020-09-14 08:03:55.265 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Starting API synchronization mode.
2020-09-14 08:03:55.590 5054-5095/com.example.amplify_android W/amplify_androi: Long monitor contention with owner pool-2-thread-1 (5094) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=1 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 288ms
2020-09-14 08:03:55.731 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Began buffering subscription events for remote mutations [class com.amplifyframework.datastore.generated.model.Todo] to Cloud models of types [ON_CREATE, ON_UPDATE, ON_DELETE].
2020-09-14 08:03:56.075 5054-5326/com.example.amplify_android I/amplify:aws-datastore: Successfully sync'd down model state from cloud.
2020-09-14 08:03:56.076 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Starting processing subscription data buffer.
2020-09-14 08:03:56.076 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Starting API synchronization mode.
2020-09-14 08:03:56.193 5054-5094/com.example.amplify_android W/amplify_androi: Long monitor contention with owner pool-2-thread-2 (5095) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=0 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 114ms
2020-09-14 08:03:56.483 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Began buffering subscription events for remote mutations [class com.amplifyframework.datastore.generated.model.Todo] to Cloud models of types [ON_CREATE, ON_UPDATE, ON_DELETE].
2020-09-14 08:03:56.887 5054-5326/com.example.amplify_android I/amplify:aws-datastore: Successfully sync'd down model state from cloud.
2020-09-14 08:03:56.888 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Starting processing subscription data buffer.
2020-09-14 08:03:56.889 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Started processing the mutation outbox. Pending mutations will be published to the cloud.
2020-09-14 08:03:56.892 5054-5088/com.example.amplify_android I/chatty: uid=10154(com.example.amplify_android) RxSingleSchedul identical 1 line
2020-09-14 08:03:56.893 5054-5088/com.example.amplify_android I/amplify:aws-datastore: Started processing the mutation outbox. Pending mutations will be published to the cloud.
2020-09-14 08:03:59.892 5054-5326/com.example.amplify_android I/amplify: retrieved todos
2020-09-14 08:03:59.892 5054-5326/com.example.amplify_android I/amplify: Todo {id=05eec008-eb4f-412e-8b41-0d096f2b36f3, name=test, description=test}
2020-09-14 08:03:59.892 5054-5326/com.example.amplify_android I/amplify: Todo {id=4af78b54-2fb8-4abe-8512-e2491a0f65d9, name=test2, description=test2} |
Hey @msiewert, thanks for creating an issue for this. Right now, the following behavior is expected: Scenario A:
The following is also expected: Scenario B:
To support Scenario A, we can add the following logic:
|
No problem, thanks for looking at this. Of the 2 scenarios outlined above, scenario B is the one failing for me. In fact, I can continue to add 'todos' after coming back online and they will sync to the backend while the ones that were added while offline will never sync. I can demonstrate this behavior. |
Interesting nuance here! Okay, this part sounds like a bug. The expected behavior here is that all models would sync in this case. |
That's correct @jamesonwilliams . Let me know what I can do to help push this forward. |
@msiewert The next part we need to understand is why the offline queue is being emptied before the items are successfully passed to the backend. If you want to start debugging that before we get to this, please check the notes in the Contributing Guide. |
@jamesonwilliams I can spend some time trying to debug, would you be able to point me to some locations in the code that would be a good starting point to look at? I have been looking at the code but still trying to understand it. |
Absolutely! I'd start by studying the state of the Also, come join us on #datastore-discussion on the Amplify Discord if you want to chat in realtime. |
@msiewert Were you able to get any more details here? What is the state of the outbox / mutation queue before / during / after the transitions? You can also try running the code again with verbose logging, and see if that helps provide any clues. Amplify.addPlugin(AndroidLoggingPlugin(LogLevel.VERBOSE))
Amplify.addPlugin(AWSApiPlugin())
Amplify.addPlugin(AWSDataStore())
Amplify.configure(applicationContext) |
Sorry, I did not. I tried but spent all my time trying to get around issues related to lack of cross platform support. I had to get back to other tasks at work. It's super easy to recreate. Every Android project I have created exhibits the behaviour. Another teammate easily created the issue as well. Shouldn't be hard for your team to diagnose. |
Same issue. |
Quite a few DataStore bugs have been resolved as of the 1.6.9 Amplify release. Several race conditions in the All of these fixes should resolve Scenario B, mentioned above. For Scenario A, the following approach is recommended:
|
Development Environment
Android Studio 4.0.1
minSdkVersion
16targetSdkVersion
30sourceCompatibility
JavaVersion.VERSION_1_8
targetCompatibility
JavaVersion.VERSION_1_8
Amplify CLI 4.29.1
Execution Environment
Famoco FX100 - https://help.famoco.com/developers/devices/FX100/
Android 24
Description
I have a simple todo application based on the tutorials.
I can demonstrate a case where I save an item in the datastore while offline (WebSocket connection errors occur) and it refuses to sync back to the backend even after connectivity is re-established.
The behavior is intermittent and does not always manifest itself, but basic steps are:
The text was updated successfully, but these errors were encountered: