DataStore synch problem during offline item saving

[target33]

Hi, this issue is related to #823 which has been closed, but actually is still a problem and is easy to recreate by using the main Android tutorial.

The problem occurs while saving an item during an offline condition, stop the program for any reason and start the program again: this way the local and remote items have a mismatch.

I'm using the latest version of Amplify Framework (1.16.13).

My environment:

• Android Studio 4.1.2
• Target API 30, minSdkVersion 26

The scenario related to #823 is neither A nor B: if you apply scenario B everything works, BUT, if you stop the program after each save, the issue is there (local data and cloud data mismatch).

So the steps to recreate the issue are:

1. Set the device in online mode (wifi or mobile data active), run the program (same one of the tutorial) from Android Studio, save an item (Item 1) inside onCreate() method.
2. Query the saved item inside the program (Amplify.DataStore.query()): check the local Item 1 is there.
3. Query the saved item inside DynamoDB or by using AppSync Console command:

   query GetTodos { listTodos { items { id name priority description } } }

   Check the remote Item 1 is there also.
   The Item 1 is correctly stored both locally and remotely.
4. Important: stop the program (Red stop button in Android Studio).
5. Set the device in offline mode (disable wifi and mobile data), run again the program from Android Studio, save a second item (Item 2) inside OnCreate() method: this item will be saved locally, not in the cloud.
6. Query the saved item inside the program (Amplify.DataStore.query()): check the local Item 2 is there.
7. Important: stop the program again (Red stop button in Android Studio).
8. Set the device in online mode again (wifi or mobile data active), run again the program from Android Studio, save a third item (Item 3) inside OnCreate() method.

Right now we expect that during step 8, the framework will save remotely both Item 2 (which was not saved in step 5 due to the lack of mobile connection) and Item 3, but only Item 3 is saved. If you query locally you'll get all three items. If you query remotely (DynamoDB and AppSync console) you get only Item 1 and 3, Item 2 is lost forever, no matter how many connections or DataStore API calls you make. If you do an Amplify.DataStore.clear() after that, Item 2 is gone forever.

This is definitely something the Framework should handle.

Let me know if you need more info to recreate the issue.

[richardmcclellan]

Hi @target33, what you are describing does sound like a bug! To help debug further, could you:

1. Call Amplify.addPlugin(AndroidLoggingPlugin(LogLevel.VERBOSE)) before Amplify.configure()
2. Share your logcat output (with any sensitive info redacted) that occurs while you are walking through the reproduction steps, particularly around step 5 (saving an item while offline) and step 8 (saving item 3 while online).

[target33]

Hi @richardmcclellan, I attached the logs.

Prerequisites: I removed manually all items previously saved in DynamoDB and performed a Amplify.DataStore.clear() to make sure no items are present both locally and remotely and the situation was the same of a brand new DataStore tutorial.

Then I started to perform the steps as indicated:

"logcat - end of step 2.txt" has been taken at the end of step 2 after a Query to check Item 1 save (online mode).
"logcat - end of step 6.txt" has been taken after saving Item 2 in offline mode and a Query to check its local saving.
"logcat - end of step 8.txt" has been taken after saving Item 3 (online mode).
"logcat - after step 8 - query without any item saving.txt" has been taken again after step 8, by restarting the program, leaving the Query for all items but removing all saving points: as you can see from the Query result, all three Items are reported correctly (local version).

If now I check the AWS AppSync Console for the following Query:

query GetTodos {
	 listTodos {
		 items {
			 id
			 name
			 priority
			 description
		 }
	 }
 }

This is the result:

{
  "data": {
	"listTodos": {
	  "items": [
		{
		  "id": "a8190e56-b530-44db-94b2-358dd59b24f6",
		  "name": "Item 1",
		  "priority": null,
		  "description": "Item 1"
		},
		{
		  "id": "f0c1e8ae-4bf1-4220-a90a-9ccbba9a95e6",
		  "name": "Item 3",
		  "priority": null,
		  "description": "Item 3"
		}
	  ]
	}
  }
}

No trace of Item 2. Same result by checking inside DynamoDB.

The code inside the MainActivity is the following (from the tutorial):

public class MainActivity extends AppCompatActivity {

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);

        try {
            Amplify.addPlugin(new AndroidLoggingPlugin(LogLevel.VERBOSE));
            Amplify.addPlugin(new AWSApiPlugin());
            Amplify.addPlugin(new AWSDataStorePlugin());
            Amplify.configure(getApplicationContext());

            Log.i("Tutorial", "Initialized Amplify");
        } catch (AmplifyException failure) {
            Log.e("Tutorial", "Could not initialize Amplify", failure);
        }

        Amplify.DataStore.observe(Todo.class,
                started -> Log.i("Tutorial", "Observation began."),
                change -> Log.i("Tutorial", change.item().toString()),
                failure -> Log.e("Tutorial", "Observation failed.", failure),
                () -> Log.i("Tutorial", "Observation complete.")
        );

//        Todo item = Todo.builder()
//                .name("Item 1")
//                .description("Item 1")
//                .build();

//        Todo item = Todo.builder()
//                .name("Item 2")
//                .description("Item 2")
//                .build();

//        Todo item = Todo.builder()
//                .name("Item 3")
//                .description("Item 3")
//                .build();

//        Amplify.DataStore.save(
//                item,
//                success -> Log.i("Tutorial", "Saved item: " + success.item().getName()),
//                error -> Log.e("Tutorial", "Could not save item to DataStore", error)
//        );

        Amplify.DataStore.query(
                Todo.class,
                todos -> {
                    while (todos.hasNext()) {
                        Todo todo = todos.next();

                        Log.i("Tutorial", "==== Todo ====");
                        Log.i("Tutorial", "ID: " + todo.getId());
                        Log.i("Tutorial", "Name: " + todo.getName());

                        if (todo.getPriority() != null) {
                            Log.i("Tutorial", "Priority: " + todo.getPriority().toString());
                        }

                        if (todo.getDescription() != null) {
                            Log.i("Tutorial", "Description: " + todo.getDescription());
                        }
                    }
                },
                failure -> Log.e("Tutorial", "Could not query DataStore", failure)
        );
    }
}

The commented lines in the middle have been uncommented during the 3 steps in order to save the 3 Items.

Let me know if you need more information.

logcat - after step 8 - query without any item saving.txt
logcat - end of step 2.txt
logcat - end of step 6.txt
logcat - end of step 8.txt

[richardmcclellan]

Thanks for providing those logs! Near the end of logcat - end of step 8.txt, I can see that two requests are sent to AppSync:

Started processing the mutation outbox. Pending mutations will be published to the cloud.
Request: {"query": "mutation CreateTodo($input: CreateTodoInput!) {\n  createTodo(input: $input) {\n    _deleted\n    _lastChangedAt\n    _version\n    description\n    id\n    name\n    priority\n  }\n}\n", "variables": {"input":{"name":null,"description":null,"id":"2c20e213-867f-4b89-8b86-b6d4196c4337","priority":null}}}
Request: {"query": "mutation CreateTodo($input: CreateTodoInput!) {\n  createTodo(input: $input) {\n    _deleted\n    _lastChangedAt\n    _version\n    description\n    id\n    name\n    priority\n  }\n}\n", "variables": {"input":{"name":"Item 3","description":"Item 3","id":"f0c1e8ae-4bf1-4220-a90a-9ccbba9a95e6","priority":null}}}

For some reason, the first request (presumably your Item 2) has null values for name, description. Are either of those fields required? If so, then the request will fail.

I'll continue to investigate and try to reproduce.

[target33]

Hi,
as you can see from logcat - after step 8 - query without any item saving.txt the id 2c20e213-867f-4b89-8b86-b6d4196c4337 is exactly Item 2:

2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: ==== Todo ====
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: ID: a8190e56-b530-44db-94b2-358dd59b24f6
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: Name: Item 1
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: Description: Item 1
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: ==== Todo ====
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: ID: 2c20e213-867f-4b89-8b86-b6d4196c4337
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: Name: Item 2
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: Description: Item 2
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: ==== Todo ====
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: ID: f0c1e8ae-4bf1-4220-a90a-9ccbba9a95e6
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: Name: Item 3
2021-02-27 12:12:30.903 28422-28464/com.example.todo I/Tutorial: Description: Item 3

But why the request to AppSync has null properties for 'name' and 'description' ? I mean, the local version has a name and description assigned correctly (and those are the only data we can handle and work with). I think something goes wrong internally during 'Amplify.DataStore.save' in offline condition.

Let me know if you are able to reproduce with the steps described (btw I think this is easily reproducible as a tech friend of mine told me he has the same issue).

[richardmcclellan]

Hi @target33, I can reproduce this bug, and am working on a fix.