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

Fatal Exception OR DataStore locks up after multiple calls to DataStore.clear() #1464

Open
1 task done
Jordan-Nelson opened this issue Aug 25, 2021 · 1 comment
Open
1 task done
Assignees
Labels
bug Something isn't working datastore DataStore category/plugins

Comments

@Jordan-Nelson
Copy link
Member

Before opening, please confirm:

Language and Async Model

Kotlin

Amplify Categories

DataStore

Gradle script dependencies

// Put output below this line
plugins {
    id 'com.android.application'
    id 'kotlin-android'
}

android {
    compileSdkVersion 30
    buildToolsVersion "30.0.3"

    defaultConfig {
        applicationId "com.example.datastoreexampleapp"
        minSdkVersion 21
        targetSdkVersion 30
        versionCode 1
        versionName "1.0"

        testInstrumentationRunner "androidx.test.runner.AndroidJUnitRunner"
    }

    buildTypes {
        release {
            minifyEnabled false
            proguardFiles getDefaultProguardFile('proguard-android-optimize.txt'), 'proguard-rules.pro'
        }
    }
    compileOptions {
        // Support for Java 8 features
        coreLibraryDesugaringEnabled true
        sourceCompatibility JavaVersion.VERSION_1_8
        targetCompatibility JavaVersion.VERSION_1_8
    }
    kotlinOptions {
        jvmTarget = '1.8'
    }
}

dependencies {
    implementation "org.jetbrains.kotlin:kotlin-stdlib:$kotlin_version"
    implementation 'androidx.core:core-ktx:1.6.0'
    implementation 'androidx.appcompat:appcompat:1.3.1'
    implementation 'com.google.android.material:material:1.4.0'
    implementation 'androidx.constraintlayout:constraintlayout:2.0.4'
    testImplementation 'junit:junit:4.+'
    androidTestImplementation 'androidx.test.ext:junit:1.1.3'
    androidTestImplementation 'androidx.test.espresso:espresso-core:3.4.0'

    // Amplify core dependency
    implementation 'com.amplifyframework:core:1.24.0'

    implementation 'com.amplifyframework:aws-datastore:1.24.0'

    // Support for Java 8 features
    coreLibraryDesugaring 'com.android.tools:desugar_jdk_libs:1.1.5'

}

Environment information

# Put output below this line
------------------------------------------------------------
Gradle 6.7.1
------------------------------------------------------------

Build time:   2020-11-16 17:09:24 UTC
Revision:     2972ff02f3210d2ceed2f1ea880f026acfbab5c0

Kotlin:       1.3.72
Groovy:       2.5.12
Ant:          Apache Ant(TM) version 1.10.8 compiled on May 10 2020
JVM:          1.8.0_291 (Oracle Corporation 25.291-b10)
OS:           Mac OS X 10.16 x86_64


Please include any relevant guides or documentation you're referencing

No response

Describe the bug

Multiple calls to DataStore.save() and DataStore.clear() in succession will either cause the app to crash, or cause DataStore to lock up, causing all other operations to fail.

Reproduction steps (if applicable)

  1. Create an app where DataStore.save() and DataStore.clear() are called multiple times in succession (see code snippet below)

Code Snippet

package com.example.datastoreexampleapp

import androidx.appcompat.app.AppCompatActivity
import android.os.Bundle
import android.util.Log
import android.view.View
import com.amplifyframework.core.Action
import com.amplifyframework.core.Amplify
import com.amplifyframework.core.Consumer
import com.amplifyframework.datastore.DataStoreItemChange
import com.amplifyframework.datastore.generated.model.Post

class MainActivity : AppCompatActivity() {
    override fun onCreate(savedInstanceState: Bundle?) {
        super.onCreate(savedInstanceState)
        setContentView(R.layout.activity_main)
    }

    fun clickButton(view: View) {
        recursiveSaveAndClear(5)
    }

    private fun recursiveSaveAndClear(count: Int) {
        Log.e("MyAmplifyApp","Save and clear count: $count")
        if (count == 0) {
            return
        }
        saveAndClear { recursiveSaveAndClear(count - 1) }
    }

    private fun saveAndClear(onComplete: Action) {
        savePost {
            clearStore(onComplete)
        }
    }

    private fun savePost(onItemSaved: Consumer<DataStoreItemChange<Post>>) {
        val post = Post.builder()
            .title("new post")
            .build()
        Amplify.DataStore.save(post,
            onItemSaved,
            { Log.e("MyAmplifyApp", "Error creating post") }
        )
    }

    private fun clearStore(onComplete: Action) {
        Amplify.DataStore.clear(
            onComplete,
            { Log.e("MyAmplifyApp", "Error clearing DataStore", it) }
        )
    }
}

Log output

Logs from a run where DataStore locked up

// Put your logs below this line

2021-08-25 12:03:48.169 29315-29315/com.example.datastoreexampleapp E/MyAmplifyApp: Save and clear count: 5
2021-08-25 12:03:48.205 29315-29315/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:03:48.222 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from STOPPED to LOCAL_ONLY
2021-08-25 12:03:48.222 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Starting to observe local storage changes.
2021-08-25 12:03:48.391 29315-29357/com.example.datastoreexampleapp I/amplify:aws-datastore: Now observing local storage. Local changes will be enqueued to mutation outbox.
2021-08-25 12:03:48.393 29315-29357/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to LOCAL_ONLY
2021-08-25 12:03:48.402 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:03:48.448 29315-29360/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:03:48.454 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from LOCAL_ONLY to STOPPED
2021-08-25 12:03:48.454 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Stopping observation of local storage changes.
2021-08-25 12:03:48.454 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to STOPPED
2021-08-25 12:03:48.457 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:03:48.473 29315-29359/com.example.datastoreexampleapp W/System.err: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
2021-08-25 12:03:48.474 29315-29359/com.example.datastoreexampleapp W/System.err: SLF4J: Defaulting to no-operation (NOP) logger implementation
2021-08-25 12:03:48.474 29315-29359/com.example.datastoreexampleapp W/System.err: SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
2021-08-25 12:03:48.548 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentModelVersion
2021-08-25 12:03:48.550 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: LastSyncMetadata
2021-08-25 12:03:48.551 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Comment
2021-08-25 12:03:48.553 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Post
2021-08-25 12:03:48.554 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentRecord
2021-08-25 12:03:48.556 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: ModelMetadata
2021-08-25 12:03:48.557 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Blog
2021-08-25 12:03:48.559 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: PersistentRecord
2021-08-25 12:03:48.560 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Post
2021-08-25 12:03:48.562 29315-29362/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Comment
2021-08-25 12:03:48.597 29315-29364/com.example.datastoreexampleapp E/MyAmplifyApp: Save and clear count: 4
2021-08-25 12:03:48.599 29315-29364/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:03:48.601 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from STOPPED to LOCAL_ONLY
2021-08-25 12:03:48.602 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Starting to observe local storage changes.
2021-08-25 12:03:48.612 29315-29366/com.example.datastoreexampleapp I/amplify:aws-datastore: Now observing local storage. Local changes will be enqueued to mutation outbox.
2021-08-25 12:03:48.613 29315-29366/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to LOCAL_ONLY
2021-08-25 12:03:48.615 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:03:48.646 29315-29367/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:03:48.649 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from LOCAL_ONLY to STOPPED
2021-08-25 12:03:48.649 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Stopping observation of local storage changes.
2021-08-25 12:03:48.651 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to STOPPED
2021-08-25 12:03:48.652 29315-29354/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:03:48.754 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentModelVersion
2021-08-25 12:03:48.756 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: LastSyncMetadata
2021-08-25 12:03:48.758 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Comment
2021-08-25 12:03:48.759 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Post
2021-08-25 12:03:48.761 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentRecord
2021-08-25 12:03:48.762 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: ModelMetadata
2021-08-25 12:03:48.764 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Blog
2021-08-25 12:03:48.765 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: PersistentRecord
2021-08-25 12:03:48.767 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Post
2021-08-25 12:03:48.769 29315-29369/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Comment
2021-08-25 12:03:48.814 29315-29371/com.example.datastoreexampleapp E/MyAmplifyApp: Save and clear count: 3
2021-08-25 12:03:48.817 29315-29371/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:03:48.820 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from STOPPED to LOCAL_ONLY
2021-08-25 12:03:48.821 29315-29355/com.example.datastoreexampleapp I/amplify:aws-datastore: Starting to observe local storage changes.
2021-08-25 12:03:48.888 29315-29372/com.example.datastoreexampleapp I/amplify:aws-datastore: Successfully enqueued PendingMutation{mutatedItem=SerializedModel{id='0799d303-7fc9-4d1e-b560-45b359ea50f0', serializedData={createdAt=null, id=0799d303-7fc9-4d1e-b560-45b359ea50f0, title=new post, updatedAt=null}, modelName=Post}, mutationType=CREATE, mutationId=0883e7f4-05be-11ec-a5dd-539cbdab70d7, predicate=MatchAllQueryPredicate}

Logs from a run where the app crashed

2021-08-25 12:13:35.336 29415-29415/com.example.datastoreexampleapp E/MyAmplifyApp: Save and clear count: 5
2021-08-25 12:13:35.399 29415-29415/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:13:35.424 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from STOPPED to LOCAL_ONLY
2021-08-25 12:13:35.424 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Starting to observe local storage changes.
2021-08-25 12:13:35.876 29415-29457/com.example.datastoreexampleapp I/amplify:aws-datastore: Now observing local storage. Local changes will be enqueued to mutation outbox.
2021-08-25 12:13:35.877 29415-29457/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to LOCAL_ONLY
2021-08-25 12:13:35.882 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:13:35.919 29415-29460/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:13:35.922 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from LOCAL_ONLY to STOPPED
2021-08-25 12:13:35.922 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Stopping observation of local storage changes.
2021-08-25 12:13:35.923 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to STOPPED
2021-08-25 12:13:35.924 29415-29455/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:13:35.934 29415-29459/com.example.datastoreexampleapp W/System.err: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
2021-08-25 12:13:35.934 29415-29459/com.example.datastoreexampleapp W/System.err: SLF4J: Defaulting to no-operation (NOP) logger implementation
2021-08-25 12:13:35.934 29415-29459/com.example.datastoreexampleapp W/System.err: SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
2021-08-25 12:13:35.996 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentModelVersion
2021-08-25 12:13:35.997 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: LastSyncMetadata
2021-08-25 12:13:35.999 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Comment
2021-08-25 12:13:36.000 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Post
2021-08-25 12:13:36.002 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentRecord
2021-08-25 12:13:36.003 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: ModelMetadata
2021-08-25 12:13:36.005 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Blog
2021-08-25 12:13:36.006 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: PersistentRecord
2021-08-25 12:13:36.008 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Post
2021-08-25 12:13:36.009 29415-29462/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Comment
2021-08-25 12:13:36.046 29415-29464/com.example.datastoreexampleapp E/MyAmplifyApp: Save and clear count: 4
2021-08-25 12:13:36.047 29415-29464/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:13:36.051 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from STOPPED to LOCAL_ONLY
2021-08-25 12:13:36.051 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Starting to observe local storage changes.
2021-08-25 12:13:36.060 29415-29466/com.example.datastoreexampleapp I/amplify:aws-datastore: Now observing local storage. Local changes will be enqueued to mutation outbox.
2021-08-25 12:13:36.060 29415-29466/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to LOCAL_ONLY
2021-08-25 12:13:36.062 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:13:36.094 29415-29467/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock acquired.
2021-08-25 12:13:36.099 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator transitioning from LOCAL_ONLY to STOPPED
2021-08-25 12:13:36.099 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Stopping observation of local storage changes.
2021-08-25 12:13:36.101 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Setting currentState to STOPPED
2021-08-25 12:13:36.101 29415-29454/com.example.datastoreexampleapp I/amplify:aws-datastore: Orchestrator lock released.
2021-08-25 12:13:36.180 29415-29470/com.example.datastoreexampleapp W/System.err: io.reactivex.rxjava3.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | DataStoreException{message=Error in saving the model: PersistentRecord[id=66a982b1-05bf-11ec-8073-8bd3021e731b], cause=java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/com.example.datastoreexampleapp/databases/AmplifyDatastore.db, recoverySuggestion=See attached exception for details.}
2021-08-25 12:13:36.181 29415-29470/com.example.datastoreexampleapp W/System.err:     at io.reactivex.rxjava3.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
2021-08-25 12:13:36.182 29415-29470/com.example.datastoreexampleapp W/System.err:     at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate$Emitter.onError(CompletableCreate.java:78)
2021-08-25 12:13:36.183 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.syncengine.-$$Lambda$wibDnzZq5mJOXI5qd8Wh_zsWeGQ.accept(Unknown Source:4)
2021-08-25 12:13:36.184 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$save$3$SQLiteStorageAdapter(SQLiteStorageAdapter.java:366)
2021-08-25 12:13:36.184 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.storage.sqlite.-$$Lambda$SQLiteStorageAdapter$0Q4t2Se5oVsIb4pxkwWPcTH3ADs.run(Unknown Source:12)
2021-08-25 12:13:36.184 29415-29470/com.example.datastoreexampleapp W/System.err:     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
2021-08-25 12:13:36.184 29415-29470/com.example.datastoreexampleapp W/System.err:     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2021-08-25 12:13:36.185 29415-29470/com.example.datastoreexampleapp W/System.err:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
2021-08-25 12:13:36.185 29415-29470/com.example.datastoreexampleapp W/System.err:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
2021-08-25 12:13:36.185 29415-29470/com.example.datastoreexampleapp W/System.err:     at java.lang.Thread.run(Thread.java:923)
2021-08-25 12:13:36.186 29415-29470/com.example.datastoreexampleapp W/System.err: Caused by: DataStoreException{message=Error in saving the model: PersistentRecord[id=66a982b1-05bf-11ec-8073-8bd3021e731b], cause=java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/com.example.datastoreexampleapp/databases/AmplifyDatastore.db, recoverySuggestion=See attached exception for details.}
2021-08-25 12:13:36.187 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$save$3$SQLiteStorageAdapter(SQLiteStorageAdapter.java:362)
2021-08-25 12:13:36.187 29415-29470/com.example.datastoreexampleapp W/System.err: 	... 6 more
2021-08-25 12:13:36.189 29415-29470/com.example.datastoreexampleapp W/System.err: Caused by: java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/com.example.datastoreexampleapp/databases/AmplifyDatastore.db
2021-08-25 12:13:36.189 29415-29470/com.example.datastoreexampleapp W/System.err:     at android.database.sqlite.SQLiteClosable.acquireReference(SQLiteClosable.java:58)
2021-08-25 12:13:36.190 29415-29470/com.example.datastoreexampleapp W/System.err:     at android.database.sqlite.SQLiteDatabase.compileStatement(SQLiteDatabase.java:1221)
2021-08-25 12:13:36.190 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.storage.sqlite.SQLCommandProcessor.executeExists(SQLCommandProcessor.java:59)
2021-08-25 12:13:36.191 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.modelExists(SQLiteStorageAdapter.java:766)
2021-08-25 12:13:36.191 29415-29470/com.example.datastoreexampleapp W/System.err:     at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$save$3$SQLiteStorageAdapter(SQLiteStorageAdapter.java:315)
2021-08-25 12:13:36.191 29415-29470/com.example.datastoreexampleapp W/System.err: 	... 6 more
2021-08-25 12:13:36.198 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentModelVersion
2021-08-25 12:13:36.200 29415-29470/com.example.datastoreexampleapp E/AndroidRuntime: FATAL EXCEPTION: pool-7-thread-2
    Process: com.example.datastoreexampleapp, PID: 29415
    io.reactivex.rxjava3.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | DataStoreException{message=Error in saving the model: PersistentRecord[id=66a982b1-05bf-11ec-8073-8bd3021e731b], cause=java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/com.example.datastoreexampleapp/databases/AmplifyDatastore.db, recoverySuggestion=See attached exception for details.}
        at io.reactivex.rxjava3.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate$Emitter.onError(CompletableCreate.java:78)
        at com.amplifyframework.datastore.syncengine.-$$Lambda$wibDnzZq5mJOXI5qd8Wh_zsWeGQ.accept(Unknown Source:4)
        at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$save$3$SQLiteStorageAdapter(SQLiteStorageAdapter.java:366)
        at com.amplifyframework.datastore.storage.sqlite.-$$Lambda$SQLiteStorageAdapter$0Q4t2Se5oVsIb4pxkwWPcTH3ADs.run(Unknown Source:12)
        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: DataStoreException{message=Error in saving the model: PersistentRecord[id=66a982b1-05bf-11ec-8073-8bd3021e731b], cause=java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/com.example.datastoreexampleapp/databases/AmplifyDatastore.db, recoverySuggestion=See attached exception for details.}
        at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$save$3$SQLiteStorageAdapter(SQLiteStorageAdapter.java:362)
        at com.amplifyframework.datastore.storage.sqlite.-$$Lambda$SQLiteStorageAdapter$0Q4t2Se5oVsIb4pxkwWPcTH3ADs.run(Unknown Source:12) 
        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: java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/com.example.datastoreexampleapp/databases/AmplifyDatastore.db
        at android.database.sqlite.SQLiteClosable.acquireReference(SQLiteClosable.java:58)
        at android.database.sqlite.SQLiteDatabase.compileStatement(SQLiteDatabase.java:1221)
        at com.amplifyframework.datastore.storage.sqlite.SQLCommandProcessor.executeExists(SQLCommandProcessor.java:59)
        at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.modelExists(SQLiteStorageAdapter.java:766)
        at com.amplifyframework.datastore.storage.sqlite.SQLiteStorageAdapter.lambda$save$3$SQLiteStorageAdapter(SQLiteStorageAdapter.java:315)
        at com.amplifyframework.datastore.storage.sqlite.-$$Lambda$SQLiteStorageAdapter$0Q4t2Se5oVsIb4pxkwWPcTH3ADs.run(Unknown Source:12) 
        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) 
2021-08-25 12:13:36.200 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: LastSyncMetadata
2021-08-25 12:13:36.202 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Comment
2021-08-25 12:13:36.204 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Post
2021-08-25 12:13:36.205 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: PersistentRecord
2021-08-25 12:13:36.207 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: ModelMetadata
2021-08-25 12:13:36.208 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating table: Blog
2021-08-25 12:13:36.209 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: PersistentRecord
2021-08-25 12:13:36.210 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Post
2021-08-25 12:13:36.213 29415-29469/com.example.datastoreexampleapp I/amplify:aws-datastore: Creating index for table: Comment
2021-08-25 12:13:36.241 29415-29470/com.example.datastoreexampleapp I/Process: Sending signal. PID: 29415 SIG: 9

amplifyconfiguration.json

No response

GraphQL Schema

type Blog @model {
  id: ID!
  name: String!
  posts: [Post] @connection(keyName: "byBlog", fields: ["id"])
}

type Post @model @key(name: "byBlog", fields: ["blogID"]) {
  id: ID!
  title: String!
  blogID: ID!
  blog: Blog @connection(fields: ["blogID"])
  comments: [Comment] @connection(keyName: "byPost", fields: ["id"])
}

type Comment @model @key(name: "byPost", fields: ["postID", "content"]) {
  id: ID!
  postID: ID!
  post: Post @connection(fields: ["postID"])
  content: String!
}

Additional information and screenshots

This was found while writing integration tests for the amplify-flutter library. Many of the tests start by performing .clear() and then perform various operations during test execution.

I was able to repro this a few different ways, all of them involving calling .clear() multiple times. Calling save and clear in succession was the simplest to reproduce.

@rjuliano rjuliano added the datastore DataStore category/plugins label Aug 26, 2021
@eeatonaws eeatonaws added the bug Something isn't working label Sep 17, 2021
@poojamat poojamat self-assigned this Sep 24, 2021
@mattcreaser
Copy link
Member

This issue is still reproducible as of Amplify 2.8.5 - there have been a lot of changes around this area however so it's unclear if this was previously fixed along the way and then regressed.

The soft-lock I'm seeing occurs in the PersistentMutationOutbox when trying to acquire the semaphore. I believe this is because we release the semaphore in doOnTerminate (instead of doFinally) which could cause it to not be released if the subscriber is disposed prior to completion.

Unfortunately a simple switch to doFinally results in crashes because of the blockingAwait() calls. This design should be revisited to see if there is an alternative approach.

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 DataStore category/plugins
Projects
None yet
Development

No branches or pull requests

6 participants