DataStoreException prevents syncing when saving same object quickly #2151

PS-MS · 2022-12-02T11:11:48Z

Before opening, please confirm:

I have searched for duplicate or closed issues and discussions.

Language and Async Model

Kotlin

Amplify Categories

GraphQL API, DataStore

Gradle script dependencies

// Put output below this line

Environment information

# Put output below this line

Please include any relevant guides or documentation you're referencing

No response

Describe the bug

Our website was failing to receive updates after saving some data, after some investigation it turned out to be developer error saving the same object multiple times. e.g.

Click save -> save data -> save event callback -> save data

DataStoreException{message=Outbox was asked to remove a mutation with ID = 18f158a3-7230-11ed-9b69-65a8d87b846b. However, there was no mutation with that ID in the outbox, to begin with.

Although it was a mistake to save twice, I'd still expect DataStore to manage the mutation id's correctly and not fall over

Reproduction steps (if applicable)

Note: the bug cause was with saving parent and child data, saving around 30 entries twice however I've been able to reproduce it with the below. If this doesn't cause the exception, increase the repeat count as it appears to be about timing.

Set up a model
Set up loop that saves in quick succession:

repeat(5) {
    Amplify.DataStore.save(modelObj)
}

Trigger code and watch debug

Code Snippet

// Put your code below this line.

Log output

// Put your logs below this line

amplifyconfiguration.json

No response

GraphQL Schema

// Put your schema below this line

Additional information and screenshots

No response

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

mikepschneider · 2022-12-06T04:15:25Z

I was able to reproduce this in a flutter app while getting a slightly different error. Once the error happens, the device db is in an inconsistent state and syncing up to the cloud is broken until the app data is reset.

The error I got looks like this:

W/amplify:aws-datastore(29489): DataStoreException{message=Wanted 1 metadata for item with id = 54452c51-6522-4d2d-8786-0861dda220c5, but had 0., cause=null, recoverySuggestion=This is likely a bug. please report to AWS.}
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.syncengine.VersionRepository.extractVersion(VersionRepository.java:91)
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.syncengine.VersionRepository.lambda$null$0$com-amplifyframework-datastore-syncengine-VersionRepository(VersionRepository.java:64)
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.syncengine.VersionRepository$$ExternalSyntheticLambda0.accept(Unknown Source:8)
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$query$4$com-amplifyframework-datastore-storage-sqlite-SQLiteStorageAdapter(SQLiteStorageAdapter.java:406)
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter$$ExternalSyntheticLambda6.run(Unknown Source:10)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:463)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
W/amplify:aws-datastore(29489): 	at java.lang.Thread.run(Thread.java:1012)
W/amplify:aws-datastore(29489): Error ended observation of mutation outbox:
W/amplify:aws-datastore(29489): DataStoreException{message=Failed to process java.lang.RuntimeException: DataStoreException{message=Wanted 1 metadata for item with id = 54452c51-6522-4d2d-8786-0861dda220c5, but had 0., cause=null, recoverySuggestion=This is likely a bug. please report to AWS.}, cause=null, recoverySuggestion=Check your internet connection.}
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.syncengine.MutationProcessor.drainMutationOutbox(MutationProcessor.java:125)
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.syncengine.MutationProcessor.lambda$startDrainingMutationOutbox$1$com-amplifyframework-datastore-syncengine-MutationProcessor(MutationProcessor.java:101)
W/amplify:aws-datastore(29489): 	at com.amplifyframework.datastore.syncengine.MutationProcessor$$ExternalSyntheticLambda3.apply(Unknown Source:4)
W/amplify:aws-datastore(29489): 	at io.reactivex.rxjava3.internal.operators.observable.ObservableFlatMapCompletableCompletable$FlatMapCompletableMainObserver.onNext(ObservableFlatMapCompletableCompletable.java:97)
W/amplify:aws-datastore(29489): 	at io.reactivex.rxjava3.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.drainNormal(ObservableObserveOn.java:201)
W/amplify:aws-datastore(29489): 	at io.reactivex.rxjava3.internal.operators.observable.ObservableObserveOn$ObserveOnObserver.run(ObservableObserveOn.java:255)
W/amplify:aws-datastore(29489): 	at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
W/amplify:aws-datastore(29489): 	at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:307)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
W/amplify:aws-datastore(29489): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
W/amplify:aws-datastore(29489): 	at java.lang.Thread.run(Thread.java:1012)

With these versions:

> flutter --version
Flutter 3.3.9 • channel stable • https://github.com/flutter/flutter.git
Framework • revision b8f7f1f986 (13 days ago) • 2022-11-23 06:43:51 +0900
Engine • revision 8f2221fbef
Tools • Dart 2.18.5 • DevTools 2.15.0


  amplify_flutter: ^0.6.10
  amplify_datastore: ^0.6.10
  amplify_auth_cognito: ^0.6.10
  amplify_api: ^0.6.10

As PS-MS mentioned, this is outside of designed usage parameters of the library, but at the same time it should not be so easy to bork the client with a common programming error.

ruchikareddy1692 · 2023-11-21T09:46:45Z

We are getting similar exception as below, is there any possible way to catch this kind of exception and continue with the sync?

DataStoreException{message=Initial cloud sync failed for RoundDetails., cause=DataStoreException{message=Failure performing sync query to AppSync., cause=ApiException{message=OkHttp client request failed., cause=java.net.SocketTimeoutException: timeout, recoverySuggestion=See attached exception for more details.}, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Check your internet connection.}

stevegaunt · 2023-12-13T16:53:35Z

Hi
@mikepschneider
@banji180

we see this...
It's more reproducible when when using a network link condition and setting to bad or poor connection..
The main scenarios I've seen this is when the mutations are a create and the update... it then ultimately tries to sync the update mutation , but it can't because the Create mutation never happened and can't retrieve the version number..

Is it possible the mutations are getting batched into an update and the create is being lost?
Ultimately this does result into data loss and should be considered a high priority bug

JeremyLabelIO · 2024-05-28T07:24:13Z

Hi,

Agree with @stevegaunt , for me it is a high priority bug because of data loss.

Is there any update ?

tylerjroach · 2024-05-28T14:15:17Z

@JeremyLabelIO What is the scenario where you are seeing data loss occur?

Is it in bad network scenarios, or is there a scenario in your application that rapidly attempts to create/update the same model. Will try and prioritize picking research back up on this ticket.

JeremyLabelIO · 2024-05-28T14:22:41Z

@JeremyLabelIO What is the scenario where you are seeing data loss occur?

Is it in bad network scenarios, or is there a scenario in your application that rapidly attempts to create/update the same model. Will try and prioritize picking research back up on this ticket.

It is in bad network scenarios. The best way to reproduce is to unplug RJ45 cable from the router (the device is still connected in WIFI but without Internet) and replug after 3 seconds. And almost everytime I have the same issue :

W/amplify:aws-datastore(28718): DataStoreException{message=Wanted 1 metadata for item with id = 76ce6b94-b309-4e72-b9d3-1c25ab23663b, but had 0., cause=null, recoverySuggestion=This is likely a bug. please report to AWS.}
W/amplify:aws-datastore(28718): 	at com.amplifyframework.datastore.syncengine.VersionRepository.extractVersion(VersionRepository.kt:147)
W/amplify:aws-datastore(28718): 	at com.amplifyframework.datastore.syncengine.VersionRepository.findModelVersion$lambda$2$lambda$0(VersionRepository.kt:62)
W/amplify:aws-datastore(28718): 	at com.amplifyframework.datastore.syncengine.VersionRepository.$r8$lambda$Fk_u2MFbRWHV25nouPsY7n5vIfE(Unknown Source:0)
W/amplify:aws-datastore(28718): 	at com.amplifyframework.datastore.syncengine.VersionRepository$$ExternalSyntheticLambda0.accept(Unknown Source:8)
W/amplify:aws-datastore(28718): 	at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$query$6$com-amplifyframework-datastore-storage-sqlite-SQLiteStorageAdapter(SQLiteStorageAdapter.java:516)
W/amplify:aws-datastore(28718): 	at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter$$ExternalSyntheticLambda9.run(Unknown Source:10)
W/amplify:aws-datastore(28718): 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:487)
W/amplify:aws-datastore(28718): 	at java.util.concurrent.FutureTask.run(FutureTask.java:264)
W/amplify:aws-datastore(28718): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
W/amplify:aws-datastore(28718): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
W/amplify:aws-datastore(28718): 	at java.lang.Thread.run(Thread.java:1012)

tylerjroach · 2024-05-28T14:45:35Z

Thanks for the additional context.

lawmicha · 2024-06-14T20:39:20Z

Hey @JeremyLabelIO, do you have the rest of the logs from run? I'm interested in what happened with the sync logs* from the first save. It should be look like

Starting attempt #1
<timestamp> amplify:aws-api         com.example.myamplifyapp             D    Request: {"query": "mutation....

*verbose logging on

Amplify.addPlugin(AndroidLoggingPlugin(LogLevel.VERBOSE))

lawmicha · 2024-07-02T14:20:54Z

We have recently released https://github.com/aws-amplify/amplify-android/releases/tag/release_v2.19.1 that has a fix for the crash. Please reach out again if you are still seeing issues, or if there are more details to share with us.

github-actions · 2024-07-02T14:21:16Z

This issue is now closed. Comments on closed issues are hard for our team to see.
If you need more assistance, please open a new issue that references this one.

banji180 added datastore DataStore category/plugins bug Something isn't working labels Dec 2, 2022

AnilMaktala added the p2 label Dec 7, 2022

mattcreaser removed the p2 label Jul 25, 2023

sktimalsina assigned tylerjroach Feb 8, 2024

tylerjroach assigned lawmicha and unassigned tylerjroach Jun 3, 2024

lawmicha mentioned this issue Jun 12, 2024

fix(DataStore): should not crash on missing version metadata #2849

Merged

6 tasks

lawmicha closed this as completed Jul 2, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DataStoreException prevents syncing when saving same object quickly #2151

DataStoreException prevents syncing when saving same object quickly #2151

PS-MS commented Dec 2, 2022

mikepschneider commented Dec 6, 2022 •

edited

Loading

ruchikareddy1692 commented Nov 21, 2023 •

edited

Loading

stevegaunt commented Dec 13, 2023

JeremyLabelIO commented May 28, 2024

tylerjroach commented May 28, 2024

JeremyLabelIO commented May 28, 2024

tylerjroach commented May 28, 2024

lawmicha commented Jun 14, 2024

lawmicha commented Jul 2, 2024

github-actions bot commented Jul 2, 2024

DataStoreException prevents syncing when saving same object quickly #2151

DataStoreException prevents syncing when saving same object quickly #2151

Comments

PS-MS commented Dec 2, 2022

Before opening, please confirm:

Language and Async Model

Amplify Categories

Gradle script dependencies

Environment information

Please include any relevant guides or documentation you're referencing

Describe the bug

Reproduction steps (if applicable)

Code Snippet

Log output

amplifyconfiguration.json

GraphQL Schema

Additional information and screenshots

mikepschneider commented Dec 6, 2022 • edited Loading

ruchikareddy1692 commented Nov 21, 2023 • edited Loading

stevegaunt commented Dec 13, 2023

JeremyLabelIO commented May 28, 2024

tylerjroach commented May 28, 2024

JeremyLabelIO commented May 28, 2024

tylerjroach commented May 28, 2024

lawmicha commented Jun 14, 2024

lawmicha commented Jul 2, 2024

github-actions bot commented Jul 2, 2024

mikepschneider commented Dec 6, 2022 •

edited

Loading

ruchikareddy1692 commented Nov 21, 2023 •

edited

Loading