DataStoreException prevents syncing when saving same object quickly

[PS-MS]

Before opening, please confirm:

• [X] 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.

1. Set up a model
2. Set up loop that saves in quick succession:

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

3. 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

[mikepschneider]

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]

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]

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]

Hi,

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

Is there any update ?

[tylerjroach]

@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]

@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]

Thanks for the additional context.

[lawmicha]

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]

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[bot]]

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.