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

DataStore saves inconsistent data to dynamoDB on a poor connection #9979

Closed
3 tasks done
duckbytes opened this issue Jun 10, 2022 · 20 comments
Closed
3 tasks done

DataStore saves inconsistent data to dynamoDB on a poor connection #9979

duckbytes opened this issue Jun 10, 2022 · 20 comments
Assignees
Labels
bug Something isn't working DataStore Related to DataStore category

Comments

@duckbytes
Copy link

duckbytes commented Jun 10, 2022

Before opening, please confirm:

JavaScript Framework

React

Amplify APIs

GraphQL API, DataStore

Amplify Categories

api

Environment information

  System:
    OS: Linux 5.18 Arch Linux
    CPU: (16) x64 AMD Ryzen 7 3700X 8-Core Processor
    Memory: 17.56 GB / 31.26 GB
    Container: Yes
    Shell: 5.9 - /bin/zsh
  Binaries:
    Node: 16.13.2 - ~/.nvm/versions/node/v16.13.2/bin/node
    Yarn: 1.22.19 - /usr/bin/yarn
    npm: 8.1.2 - ~/.nvm/versions/node/v16.13.2/bin/npm
  Browsers:
    Firefox: 101.0.1
  npmPackages:
    @aws-amplify/ui-react: ^2.19.1 => 2.19.1
    @aws-amplify/ui-react-internal:  undefined ()
    @aws-amplify/ui-react-legacy:  undefined ()
    @peculiar/webcrypto: ^1.3.2 => 1.3.2
    @testing-library/jest-dom: ^5.16.2 => 5.16.2
    @testing-library/react: ^12.1.4 => 12.1.4
    @testing-library/user-event: ^13.5.0 => 13.5.0
    aws-amplify: ^4.3.24 => 4.3.24
    graphql: ^16.3.0 => 16.3.0 (15.8.0)
    react: ^17.0.2 => 17.0.2
    react-dom: ^17.0.2 => 17.0.2
    react-scripts: 5.0.0 => 5.0.0
    web-vitals: ^2.1.4 => 2.1.4
  npmGlobalPackages:
    @aws-amplify/cli: 8.4.0
    corepack: 0.10.0
    npm: 8.1.2


Describe the bug

When making changes too fast to a record, mutations to the API are missed or send incorrect data.

An observer will also react and return the UI into an old state that reflects the out of date mutation.

The problem is more obvious when on a slow network connection, and in real world testing has caused data to be saved incorrectly with normal usage. When offline, data is synced correctly once a connection is re-established.

I also find the problem occurs when testing with Cypress at full network speed.

I use an observer to make sure that the record has one field set before enabling a button to set the next field. However I have observed this issue when changing a single field repeatedly.

One workaround is to check that _version has incremented before allowing further mutations. However this prevents it from working offline as that value is never incremented until data is sent to the API.

In my example I'm setting two fields: status and a time stamp. But it does seem to happen when setting one field too.

Expected behavior

DataStore should always sync changes to the record and not miss changes. The observer should not update with incorrect data.

Reproduction steps

  • open the example in Chrome
  • open dev tools and in the console: await DataStore.save(new models.Task({}))
  • copy the new ID to taskId
  • (if console says task not found, refresh the page)
  • go to Network tab. Change No throttling to Slow 3G
  • update the record by clicking the check boxes multiple times. previous check box should be disabled until the observer updates
  • the status should appear at the top
  • buttons that are enabled appear under the checkboxes
  • observe mutations in the Network tab
  • observe changes in the UI

Code Snippet

enum TaskStatus {
  ACTIVE
  PICKED_UP
  DROPPED_OFF
  COMPLETED
}

type Task @model @auth(rules: [{ allow: public }]) {
  id: ID!
  status: TaskStatus
  timePickedUp: AWSDateTime
  timeDroppedOff: AWSDateTime
  timeRiderHome: AWSDateTime
}

src/App.js

import "./App.css";
import React, { useRef, useState } from "react";
import { Amplify, DataStore } from "aws-amplify";
import awsconfig from "./aws-exports";
import { useEffect } from "react";
import * as models from "./models";

window.DataStore = DataStore;
window.models = models;
Amplify.configure(awsconfig);

const fields = {
  timePickedUp: "Picked up",
  timeDroppedOff: "Delivered",
  timeRiderHome: "Rider home",
};

export const tasksStatus = {
  active: "ACTIVE",
  pickedUp: "PICKED_UP",
  droppedOff: "DROPPED_OFF",
  completed: "COMPLETED",
};

export function determineTaskStatus(task) {
  if (!!!task.timePickedUp) {
    return tasksStatus.active;
  } else if (!!task.timePickedUp && !!!task.timeDroppedOff) {
    return tasksStatus.pickedUp;
  } else if (
    !!task.timePickedUp &&
    !!task.timeDroppedOff &&
    !!!task.timeRiderHome
  ) {
    return tasksStatus.droppedOff;
  } else if (
    !!task.timePickedUp &&
    !!task.timeDroppedOff &&
    !!task.timeRiderHome
  ) {
    return tasksStatus.completed;
  }
}

async function saveTaskTimeWithKey(key, value, taskId) {
  let isoString = null;
  if (value) {
    isoString = new Date(value).toISOString();
  }
  const existingTask = await DataStore.query(models.Task, taskId);
  if (!existingTask) throw new Error("Task doesn't exist");
  const status = await determineTaskStatus({
    ...existingTask,
    [key]: isoString,
  });
  return DataStore.save(
    models.Task.copyOf(existingTask, (updated) => {
      updated[key] = value ? isoString : null;
      updated.status = status;
    })
  );
}

function App() {
  const [state, setState] = useState([]);
  const [task, setTask] = useState(null);
  const [isPosting, setIsPosting] = useState(false);
  const taskObserver = useRef({ unsubscribe: () => {} });
  const timeSet = useRef(null);
  const taskId = "38b35b73-2b4a-406a-bcf0-de0bc56ee8d0";
  const prevVersion = useRef(null);

  function checkDisabled(key) {
    const stopped =
      state.includes("timeCancelled") || state.includes("timeRejected");
    if (key === "timeDroppedOff")
      return (
        state.includes("timeRiderHome") ||
        !state.includes("timePickedUp") ||
        stopped
      );
    else if (key === "timePickedUp") {
      return state.includes("timeDroppedOff") || stopped;
    } else if (key === "timeRiderHome") {
      if (task && task.status === tasksStatus.new) return true;
      return !state.includes("timeDroppedOff");
    } else if (key === "timeRejected") {
      if (state.includes("timeRejected")) return false;
      return (
        (state.includes("timePickedUp") && state.includes("timeDroppedOff")) ||
        stopped
      );
    } else if (key === "timeCancelled") {
      if (state.includes("timeCancelled")) return false;
      return (
        (state.includes("timePickedUp") && state.includes("timeDroppedOff")) ||
        stopped
      );
    } else return false;
  }

  async function setTimeWithKey(key, value) {
    try {
      setIsPosting(true);
      await saveTaskTimeWithKey(key, value, taskId);
      setIsPosting(false);
    } catch (error) {
      console.log(error);
    }
  }

  async function getTaskAndUpdateState() {
    try {
      const task = await DataStore.query(models.Task, taskId);
      if (!task) throw new Error("Task not found");
      setTask(task);
      taskObserver.current.unsubscribe();
      taskObserver.current = DataStore.observe(models.Task, taskId).subscribe(
        async ({ opType, element }) => {
          if (
            ["INSERT", "UPDATE"].includes(opType)
            // uncomment for a fix that only works while online
            //&& element._version > prevVersion.current
          ) {
            console.log(element);
            setTask(element);
            prevVersion.current = element._version;
          }
        }
      );
    } catch (e) {
      console.log(e);
    }
  }
  useEffect(() => getTaskAndUpdateState(), []);

  function calculateState() {
    if (!task) return;
    const result = Object.keys(fields).filter((key) => {
      return !!task[key];
    });
    setState(result);
  }
  useEffect(calculateState, [task]);

  function onClickToggle(key, checked) {
    timeSet.current = new Date();
    setTimeWithKey(key, !checked ? null : new Date());
  }

  return (
    <div>
      {task ? task.status : ""}
      <div>
        <form class="form">
          {Object.entries(fields).map(([key, label]) => {
            return (
              <label>
                {label}
                <input
                  type="checkbox"
                  disabled={isPosting || checkDisabled(key)}
                  onChange={(e) => onClickToggle(key, e.target.checked)}
                  checked={state.includes(key)}
                />
              </label>
            );
          })}
        </form>
      </div>
      <div sx={{ width: "100%" }} direction="column">
        {Object.entries(fields).map(([key, value]) => {
          const disabled = isPosting || checkDisabled(key);
          return (
            !disabled && (
              <div>
                {value.toUpperCase()}
              </div>
            )
          );
        })}
      </div>
    </div>
  );
}

export default App;

src/App.css

.form {
  display: flex;
  flex-direction: column;
  justify-content: center;
  align-items: flex-end;
  max-width: 120px;
}

Log output


ConsoleLogger.ts:125 [DEBUG] 01:01.814 DataStore - params ready {predicate: {…}, pagination: {…}, modelConstructor: ƒ}
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'DROPPED_OFF', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 01:01.852 DataStore - Attempting mutation with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 01:01.852 Util -  attempt #1 with this vars: ["Task","Update","{\"timeRiderHome\":null,\"status\":\"DROPPED_OFF\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":316,\"_lastChangedAt\":1654826451258,\"_deleted\":null}","{}",null,null,{"data":"{\"timeRiderHome\":null,\"status\":\"DROPPED_OFF\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":316,\"_lastChangedAt\":1654826451258,\"_deleted\":null}","modelId":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","model":"Task","operation":"Update","condition":"{}","id":"01G55M7Q5TB189H8P2QFKV0F35"}]
ConsoleLogger.ts:125 [DEBUG] 01:01.853 RestClient - POST https://xpbl3vag25afng2n6ishxbo74y.appsync-api.eu-west-1.amazonaws.com/graphql
ConsoleLogger.ts:125 [DEBUG] 01:02.110 DataStore - params ready {predicate: {…}, pagination: {…}, modelConstructor: ƒ}
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'PICKED_UP', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: null, timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 01:02.145 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"id":"55de9349-e5e3-4391-9ff0-daa8235c61a2","type":"data","payload":{"data":{"onUpdateTask":{"id":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","status":"DROPPED_OFF","timePickedUp":"2022-06-10T01:52:35.587Z","timeDroppedOff":"2022-06-10T02:00:34.696Z","timeCancelled":null,"timeRejected":null,"timeRiderHome":null,"createdAt":"2022-06-09T18:38:06.466Z","updatedAt":"2022-06-10T02:01:01.912Z","_version":317,"_lastChangedAt":1654826461927,"_deleted":null}}}}
ConsoleLogger.ts:118 [DEBUG] 01:02.145 AWSAppSyncRealTimeProvider {id: '55de9349-e5e3-4391-9ff0-daa8235c61a2', observer: SubscriptionObserver, query: 'subscription operation {\n  onUpdateTask {\n    id\n …  _version\n    _lastChangedAt\n    _deleted\n  }\n}\n', variables: {…}}
ConsoleLogger.ts:125 [DEBUG] 01:02.384 DataStore - params ready {predicate: {…}, pagination: {…}, modelConstructor: ƒ}
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'ACTIVE', timePickedUp: null, timeDroppedOff: null, timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 01:03.886 DataStore - Mutation sent successfully with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 01:03.909 DataStore - Attempting mutation with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 01:03.909 Util -  attempt #1 with this vars: ["Task","Update","{\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":316,\"_lastChangedAt\":1654826451258,\"_deleted\":null,\"timeDroppedOff\":null,\"status\":\"ACTIVE\",\"timePickedUp\":null}","{}",null,null,{"data":"{\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":316,\"_lastChangedAt\":1654826451258,\"_deleted\":null,\"timeDroppedOff\":null,\"status\":\"ACTIVE\",\"timePickedUp\":null}","modelId":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","model":"Task","operation":"Update","condition":"{}","id":"01G55M7Q5TB189H8P2QFKV0F37"}]
ConsoleLogger.ts:125 [DEBUG] 01:03.910 RestClient - POST https://xpbl3vag25afng2n6ishxbo74y.appsync-api.eu-west-1.amazonaws.com/graphql
ConsoleLogger.ts:115 [DEBUG] 01:04.214 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"id":"55de9349-e5e3-4391-9ff0-daa8235c61a2","type":"data","payload":{"data":{"onUpdateTask":{"id":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","status":"DROPPED_OFF","timePickedUp":"2022-06-10T01:52:35.587Z","timeDroppedOff":"2022-06-10T02:00:34.696Z","timeCancelled":null,"timeRejected":null,"timeRiderHome":null,"createdAt":"2022-06-09T18:38:06.466Z","updatedAt":"2022-06-10T02:01:01.912Z","_version":318,"_lastChangedAt":1654826464061,"_deleted":null}}}}
ConsoleLogger.ts:118 [DEBUG] 01:04.214 AWSAppSyncRealTimeProvider {id: '55de9349-e5e3-4391-9ff0-daa8235c61a2', observer: SubscriptionObserver, query: 'subscription operation {\n  onUpdateTask {\n    id\n …  _version\n    _lastChangedAt\n    _deleted\n  }\n}\n', variables: {…}}
ConsoleLogger.ts:115 [DEBUG] 01:05.927 DataStore - Mutation sent successfully with authMode: API_KEY
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'DROPPED_OFF', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 01:10.215 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"}
ConsoleLogger.ts:118 [DEBUG] 01:10.228 AWSAppSyncRealTimeProvider {id: '', observer: null, query: '', variables: {…}}
ConsoleLogger.ts:125 [DEBUG] 02:04.837 DataStore - params ready {predicate: {…}, pagination: {…}, modelConstructor: ƒ}
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'COMPLETED', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 02:04.895 DataStore - Attempting mutation with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 02:04.896 Util -  attempt #1 with this vars: ["Task","Update","{\"timeRiderHome\":\"2022-06-10T02:02:04.836Z\",\"status\":\"COMPLETED\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":318,\"_lastChangedAt\":1654826464061,\"_deleted\":null}","{}",null,null,{"data":"{\"timeRiderHome\":\"2022-06-10T02:02:04.836Z\",\"status\":\"COMPLETED\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":318,\"_lastChangedAt\":1654826464061,\"_deleted\":null}","modelId":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","model":"Task","operation":"Update","condition":"{}","id":"01G55M7Q5TB189H8P2QFKV0F38"}]
ConsoleLogger.ts:125 [DEBUG] 02:04.896 RestClient - POST https://xpbl3vag25afng2n6ishxbo74y.appsync-api.eu-west-1.amazonaws.com/graphql
ConsoleLogger.ts:115 [DEBUG] 02:05.204 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"id":"55de9349-e5e3-4391-9ff0-daa8235c61a2","type":"data","payload":{"data":{"onUpdateTask":{"id":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","status":"COMPLETED","timePickedUp":"2022-06-10T01:52:35.587Z","timeDroppedOff":"2022-06-10T02:00:34.696Z","timeCancelled":null,"timeRejected":null,"timeRiderHome":"2022-06-10T02:02:04.836Z","createdAt":"2022-06-09T18:38:06.466Z","updatedAt":"2022-06-10T02:02:04.971Z","_version":319,"_lastChangedAt":1654826525012,"_deleted":null}}}}
ConsoleLogger.ts:118 [DEBUG] 02:05.204 AWSAppSyncRealTimeProvider {id: '55de9349-e5e3-4391-9ff0-daa8235c61a2', observer: SubscriptionObserver, query: 'subscription operation {\n  onUpdateTask {\n    id\n …  _version\n    _lastChangedAt\n    _deleted\n  }\n}\n', variables: {…}}
ConsoleLogger.ts:115 [DEBUG] 02:06.917 DataStore - Mutation sent successfully with authMode: API_KEY
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'COMPLETED', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}
ConsoleLogger.ts:125 [DEBUG] 02:09.126 DataStore - params ready {predicate: {…}, pagination: {…}, modelConstructor: ƒ}
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'DROPPED_OFF', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 02:09.162 DataStore - Attempting mutation with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 02:09.162 Util -  attempt #1 with this vars: ["Task","Update","{\"timeRiderHome\":null,\"status\":\"DROPPED_OFF\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":319,\"_lastChangedAt\":1654826525012,\"_deleted\":null}","{}",null,null,{"data":"{\"timeRiderHome\":null,\"status\":\"DROPPED_OFF\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":319,\"_lastChangedAt\":1654826525012,\"_deleted\":null}","modelId":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","model":"Task","operation":"Update","condition":"{}","id":"01G55M7Q5TB189H8P2QFKV0F39"}]
ConsoleLogger.ts:125 [DEBUG] 02:09.163 RestClient - POST https://xpbl3vag25afng2n6ishxbo74y.appsync-api.eu-west-1.amazonaws.com/graphql
ConsoleLogger.ts:115 [DEBUG] 02:09.494 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"id":"55de9349-e5e3-4391-9ff0-daa8235c61a2","type":"data","payload":{"data":{"onUpdateTask":{"id":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","status":"DROPPED_OFF","timePickedUp":"2022-06-10T01:52:35.587Z","timeDroppedOff":"2022-06-10T02:00:34.696Z","timeCancelled":null,"timeRejected":null,"timeRiderHome":null,"createdAt":"2022-06-09T18:38:06.466Z","updatedAt":"2022-06-10T02:02:09.217Z","_version":320,"_lastChangedAt":1654826529232,"_deleted":null}}}}
ConsoleLogger.ts:118 [DEBUG] 02:09.494 AWSAppSyncRealTimeProvider {id: '55de9349-e5e3-4391-9ff0-daa8235c61a2', observer: SubscriptionObserver, query: 'subscription operation {\n  onUpdateTask {\n    id\n …  _version\n    _lastChangedAt\n    _deleted\n  }\n}\n', variables: {…}}
ConsoleLogger.ts:125 [DEBUG] 02:09.694 DataStore - params ready {predicate: {…}, pagination: {…}, modelConstructor: ƒ}
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'COMPLETED', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}
ConsoleLogger.ts:115 [DEBUG] 02:10.214 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"}
ConsoleLogger.ts:118 [DEBUG] 02:10.214 AWSAppSyncRealTimeProvider {id: '', observer: null, query: '', variables: {…}}
ConsoleLogger.ts:115 [DEBUG] 02:11.206 DataStore - Mutation sent successfully with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 02:11.227 DataStore - Attempting mutation with authMode: API_KEY
ConsoleLogger.ts:115 [DEBUG] 02:11.227 Util -  attempt #1 with this vars: ["Task","Update","{\"timeRiderHome\":\"2022-06-10T02:02:09.692Z\",\"status\":\"COMPLETED\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":319,\"_lastChangedAt\":1654826525012,\"_deleted\":null}","{}",null,null,{"data":"{\"timeRiderHome\":\"2022-06-10T02:02:09.692Z\",\"status\":\"COMPLETED\",\"id\":\"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0\",\"_version\":319,\"_lastChangedAt\":1654826525012,\"_deleted\":null}","modelId":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","model":"Task","operation":"Update","condition":"{}","id":"01G55M7Q5TB189H8P2QFKV0F3A"}]
ConsoleLogger.ts:125 [DEBUG] 02:11.228 RestClient - POST https://xpbl3vag25afng2n6ishxbo74y.appsync-api.eu-west-1.amazonaws.com/graphql
ConsoleLogger.ts:115 [DEBUG] 02:11.535 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"id":"55de9349-e5e3-4391-9ff0-daa8235c61a2","type":"data","payload":{"data":{"onUpdateTask":{"id":"38b35b73-2b4a-406a-bcf0-de0bc56ee8d0","status":"DROPPED_OFF","timePickedUp":"2022-06-10T01:52:35.587Z","timeDroppedOff":"2022-06-10T02:00:34.696Z","timeCancelled":null,"timeRejected":null,"timeRiderHome":"2022-06-10T02:02:09.692Z","createdAt":"2022-06-09T18:38:06.466Z","updatedAt":"2022-06-10T02:02:09.217Z","_version":321,"_lastChangedAt":1654826531350,"_deleted":null}}}}
ConsoleLogger.ts:118 [DEBUG] 02:11.535 AWSAppSyncRealTimeProvider {id: '55de9349-e5e3-4391-9ff0-daa8235c61a2', observer: SubscriptionObserver, query: 'subscription operation {\n  onUpdateTask {\n    id\n …  _version\n    _lastChangedAt\n    _deleted\n  }\n}\n', variables: {…}}
ConsoleLogger.ts:115 [DEBUG] 02:13.248 DataStore - Mutation sent successfully with authMode: API_KEY
App.js:126 Model {id: '38b35b73-2b4a-406a-bcf0-de0bc56ee8d0', status: 'DROPPED_OFF', timePickedUp: '2022-06-10T01:52:35.587Z', timeDroppedOff: '2022-06-10T02:00:34.696Z', timeCancelled: null, …}

aws-exports.js

const awsmobile = {
    "aws_project_region": "eu-west-1",
    "aws_appsync_graphqlEndpoint": "https://xpbl3vag25afng2n6ishxbo74y.appsync-api.eu-west-1.amazonaws.com/graphql",
    "aws_appsync_region": "eu-west-1",
    "aws_appsync_authenticationType": "API_KEY",
    "aws_appsync_apiKey": "da2-vs6oo7xssvdn7lnqbpene4fmla",
    "aws_cognito_identity_pool_id": "eu-west-1:7bbed19f-d205-4101-9829-ebfa833ec06d",
    "aws_cognito_region": "eu-west-1",
    "aws_user_pools_id": "eu-west-1_VD0AQtRSn",
    "aws_user_pools_web_client_id": "63l0hbdlt41u10th59cnfom53c",
    "oauth": {},
    "aws_cognito_username_attributes": [],
    "aws_cognito_social_providers": [],
    "aws_cognito_signup_attributes": [
        "EMAIL"
    ],
    "aws_cognito_mfa_configuration": "OFF",
    "aws_cognito_mfa_types": [
        "SMS"
    ],
    "aws_cognito_password_protection_settings": {
        "passwordPolicyMinLength": 8,
        "passwordPolicyCharacters": []
    },
    "aws_cognito_verification_mechanisms": [
        "EMAIL"
    ]
};


export default awsmobile;

Manual configuration

No response

Additional configuration

No response

Mobile Device

No response

Mobile Operating System

No response

Mobile Browser

No response

Mobile Browser Version

No response

Additional information and screenshots

A video demonstration (sorry for quality, the webm looked much better but github won't attach it):

output.mp4

An example of where the status field mismatches what was sent to the API (timeRiderHome, timeDroppedOff and timePickedUp all being set means the status should be COMPLETED). This doesn't always happen, but does often.

Screenshot from 2022-06-10 02-53-11

The entry in dynamoDB where the status doesn't match:

image

@chrisbonifacio chrisbonifacio added DataStore Related to DataStore category pending-triage Issue is pending triage labels Jun 10, 2022
@undefobj
Copy link
Contributor

@duckbytes We reviewed this yesterday and can reproduce, it looks to be a specific race condition as you've identified during in-flight network requests. In order to address this though it would be helpful to see the Cypress tests as well. Can you share those?

@undefobj undefobj added the bug Something isn't working label Jun 11, 2022
@duckbytes
Copy link
Author

Hey @undefobj. Thanks for looking into it.

Cypress.Commands.add("addSingleTask", () => {
    cy.get("[data-cy=NEW-title-skeleton]", { timeout: 10000 }).should(
        "not.exist"
    );
    cy.get(".MuiPaper-root").should("be.visible");
    cy.get("[data-cy=create-task-button]").click();
    cy.get("[data-cy=save-to-dash-button]").click();
});

Cypress.Commands.add("loginByCognitoApi", (username, password) => {
    const log = Cypress.log({
        displayName: "COGNITO LOGIN",
        message: [`🔐 Authenticating | ${username}`],
        // @ts-ignore
        autoEnd: false,
    });

    log.snapshot("before");

    const signIn = Auth.signIn({ username, password });

    cy.wrap(signIn, { log: false }).then((cognitoResponse) => {
        const keyPrefixWithUsername = `${cognitoResponse.keyPrefix}.${cognitoResponse.username}`;

        window.localStorage.setItem(
            `${keyPrefixWithUsername}.idToken`,
            cognitoResponse.signInUserSession.idToken.jwtToken
        );

        window.localStorage.setItem(
            `${keyPrefixWithUsername}.accessToken`,
            cognitoResponse.signInUserSession.accessToken.jwtToken
        );

        window.localStorage.setItem(
            `${keyPrefixWithUsername}.refreshToken`,
            cognitoResponse.signInUserSession.refreshToken.token
        );

        window.localStorage.setItem(
            `${keyPrefixWithUsername}.clockDrift`,
            cognitoResponse.signInUserSession.clockDrift
        );

        window.localStorage.setItem(
            `${cognitoResponse.keyPrefix}.LastAuthUser`,
            cognitoResponse.username
        );

        window.localStorage.setItem(
            "amplify-authenticator-authState",
            "signedIn"
        );
        log.snapshot("after");
        log.end();
    });

    cy.visit("/");
});

describe("task actions", () => {
    beforeEach(() => {
        cy.loginByCognitoApi(Cypress.env("username"), Cypress.env("password"));
    });

    it("picked up, delivered, rider home", () => {
        cy.visit("/");
        cy.addSingleTask();
        cy.get("[data-cy=tasks-kanban-column-NEW]").children().first().click();
        cy.get("[data-cy=combo-box-riders]").click().type("Test Rider");
        cy.get('[id*="option-0"]').should("exist");
        cy.get('[id*="option-0"]').click();
        cy.get("[data-cy=task-status]").should("have.text", "ACTIVE");
        cy.get("[data-cy=task-RIDER-assignees]").contains("Test Rider");
        cy.get("[data-cy=task-timePickedUp-button]").should("be.enabled");
        cy.get("[data-cy=task-timePickedUp-button]").click();
        cy.get("[data-cy=confirmation-ok-button]").click();
        cy.get("[data-cy=task-status]").should("have.text", "PICKED UP");
        cy.get("[data-cy=task-timeDroppedOff-button]").should("be.enabled");
        cy.get("[data-cy=task-timeDroppedOff-button]").click();
        cy.get("[data-cy=confirmation-ok-button]").click();
        cy.get("[data-cy=task-status]").should("have.text", "DELIVERED");
        cy.get("[data-cy=task-timeRiderHome-button]").should("be.enabled");
        cy.get("[data-cy=task-timeRiderHome-button]").click();
        cy.get("[data-cy=confirmation-ok-button]").click();
        cy.get("[data-cy=task-status]").should("have.text", "COMPLETED");
    });
});

This is the Cypress code. A lot of it applies to my app and not the example I made, but it might be helpful anyway.

@duckbytes
Copy link
Author

duckbytes commented Jun 11, 2022

The Cypress test is interesting because in this case the network tab shows what looks like a correct mutation, but the observer returns the status in the top bar back to delivered:

Screenshot from 2022-06-12 00-49-56

The test also passes because the UI does show completed for a moment before the observer catches up and puts it back to delivered.

But the dynamodb record has the incorrect status again:

Screenshot from 2022-06-12 00-51-40

This mismatch of recorded data seems to be reproducible for every run of the test.

Edit to add: not sure if it's helpful too but these are the the unit tests that demonstrate exactly what I'm doing with DataStore underneath https://github.com/platelet-app/platelet/blob/master/src/scenes/Task/components/TaskActions.test.js

@undefobj
Copy link
Contributor

@duckbytes thank you for this. We have determined the issue is due to a comparison problem between changed fields on the clients and the network response when using AutoMerge. We have a plan to solve this but it will take some care on our side for this scenario with testing. In the meantime if you are blocked on this particular behavior we would suggest switching your Conflict Resolution strategy to Optimistic Concurrency rather than AutoMerge if possible.

@duckbytes
Copy link
Author

Thanks @undefobj switching to optimistic concurrency looks to have fixed it.

@frankarnaud
Copy link

Hello, allow me to join this discussion to say that indeed we were facing a problem without understanding the cause. Eventually I stumbled across this thread and came to the same conclusion. We are developing a stock management application and unfortunately the inconsistencies that have arisen affect the satisfaction of our customers. Amplify is a wonderful tool and we appreciate the efforts made so far to resolve the issues we are having. We are still waiting for a definitive solution. Regards

@chrisbonifacio
Copy link
Contributor

@frankarnaud thank you! We are currently focused on completing and releasing support for Custom Primary & Composite Keys in DataStore. However, the work for this fix is already up for review and will be scheduled for released afterwards. Please stay tuned for more updates!

@dmitrytenera
Copy link

We too have an issue with DataStore thinking that all of the records have been synced to cloud (sending outboxStatus event with empty payload), but in reality these records are not persisted in DynamoDB. This often happens when we use our application in an area with poor network connectivity. Everything works when the app is completely online or completely offline. Things start breaking when the network connection varies in strength (e.g. good connection - bad connection - no connection - etc). Most of our users use the app in these network conditions. We tried following the suggestion in this thread and switched to Optimistic Concurrency conflict resolution strategy, but it seems to have little effect.

Steps to reproduce: drive out of town until you get 3G cell signal with 0-2 bars. Create 100 entities in DataStore while walking in a line between two spots where signal strength varies. Return to the area with good Internet connection and observe up to 10% of the records missing in DynamoDB. Even after returning to good Internet connection, DataStore will not attempt to sync the remaining records as it thinks that there is nothing left to sync.

@dmitrytenera
Copy link

Since this was a critical blocker for us, we ended up writing custom logic that listens for DataStore event that claims all records are synced. It then queries all model types and iterates over the results to find records with _version === undefined. For each such record, we submit a worker that calls AppSync API to create the record, then DataStore.query with that record ID predicate to force refresh it with the latest values. This is using AUTO_MERGE conflict resolution strategy. We are also using a token-based retry strategy in case we go offline and the worker is not able to complete its job.

@dmitrytenera
Copy link

We also found an easier way to achieve the described end result. In Chrome:

  1. Go offline in Network profiles
  2. Clear cookies in Application tab
  3. Create a model via DataStore
  4. Go online (no throttling)
  5. Refresh the page
  6. Login

DataStore will send an event indicating that there is nothing to sync, but the un-synced model record will remain stored in the local IndexedDB table with undefined _version etc. attributes.

@chrisbonifacio
Copy link
Contributor

chrisbonifacio commented Sep 2, 2022

The PR with the fix for this issue has been reviewed and approved, soon to be released in the coming weeks. I would keep an eye on that PR, we will later comment here when the fix is officially available.

@iartemiev iartemiev self-assigned this Sep 7, 2022
@svidgen
Copy link
Contributor

svidgen commented Sep 7, 2022

@chrisbonifacio Sorry if this was miscommunicated, but that PR doesn't doesn't solve this problem. It solves a problem with .clear() and .stop() that was interfering with the reproduction of this problem in the test suite.

But, @iartemiev is starting work on the fix today, which we may initially release under a tag for testing.

@duckbytes
Copy link
Author

Are there downsides or considerations to take when using optimistic concurrency until this is fixed?

I found documentation here about writing a conflict resolution function https://docs.amplify.aws/lib/datastore/conflict/q/platform/js/#custom-configuration

Is there any recommended logic to use there until we can go back to using auto-merge?

@dmitrytenera
Copy link

@svidgen Just to confirm, will @iartemiev work address the issue with the DataStore missing propagation of local updates to AppSync on spotty Internet connection? Have you been able to reproduce it? The fact that switching conflict resolution to optimistic concurrency helped some users but not others makes me wonder if there are two different issues.

@dmitrytenera
Copy link

dmitrytenera commented Sep 12, 2022

Are there downsides or considerations to take when using optimistic concurrency until this is fixed?

I found documentation here about writing a conflict resolution function https://docs.amplify.aws/lib/datastore/conflict/q/platform/js/#custom-configuration

Is there any recommended logic to use there until we can go back to using auto-merge?

@duckbytes Not sure if this helps, but switching to optimistic concurrency broke our auto-increment logic where we issue an empty GraphQL update to atomically increment the Counter model _version attribute. To make it work with optimistic concurrency, we would have to query the record first for the latest _version, then make an update with the latest _version value known to client. This could fail if there are many concurrent updates on the same record as it is prone to race conditions.

Optimistic concurrency didn't resolve the DataStore issue for us, so we simply switched back to auto-merge.

@duckbytes
Copy link
Author

Has there been any progress or new information on this issue? Or potential workarounds?

I'm having some difficulty with optimistic concurrency and trying to resolve conflicts manually, as well as coming up against bugs (#11708). I'd like to try auto-merge again if possible.

@arundna
Copy link

arundna commented Sep 8, 2023

@duckbytes - We have a plan to improve the experience with Auto Merge but it is still work in progress due to the underlying complexity of the fix. Our recommendation in general, is to use Optimistic Concurrency. I understand that you're facing bug #11708 and we'll investigate that in parallel to unblock you from continuing to use optimistic concurrency.

@stocaaro
Copy link
Contributor

stocaaro commented Jan 11, 2024

Hello @duckbytes,

We really appreciate the time and detail you've put into this issue. A fix was merged this week and is now available on "aws-amplify": "unstable" which resolves the sequencing bug for several of my sample apps; constructed based on your notes.

This fix will be published to latest with the next release, currently scheduled for today. I'll be doing more testing around this on my end. If you have the opportunity to test against unstable today or latest for any aws-amplify version > 6.0.11, it would be good to get your confirmation that the problem is fixed for your app as well.

Thanks!
Aaron

@duckbytes
Copy link
Author

Thanks very much @stocaaro for your work on this!

My web version is still on Amplify V4 because of the breaking changes in DataStore, so I won't be able to switch over to automerge and test until I can do the work to migrate everything over. The smartphone app is on Amplify V5 though, so I will get that up to date soon.

@stocaaro
Copy link
Contributor

Sounds good @duckbytes,

From the testing I’ve done, I believe this problem is solved in the current V6 release. I’m going to close this issue. If you get your applications updated and are seeing issues that look related in any way, please comment here (or on a new issue linked back to this one) with details.

Thanks,
Aaron

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 Related to DataStore category
Projects
None yet
Development

No branches or pull requests