Updates not getting materialized

[adzialocha]

Sending a CREATE operation, followed by 2 UPDATE operations do sometimes not get materialized:

const chat = await Chat.create({
  message: '1',
});

await chat.update({
  message: '2',
});

await chat.update({
  message: '3',
});

.. the playground sometimes materializes only up to 1, sometimes 2, sometimes 3:

{
  "data": {
    "all_chat_002009a6721c3015eb87a7b941e5d54183b7bd209c72dec05af234ede47dd4772f35": [
      {
        "fields": {
          "message": "3"
        }
      },
      {
        "fields": {
          "message": "1"
        }
      },
      {
        "fields": {
          "message": "2"
        }
      }
    ]
  }
}

Steps to reproduce:

1. Check out document-orm branch in shirokuma: https://github.com/p2panda/shirokuma/tree/document-orm, build the package via npm run build
2. Run aquadoggo from main w. new database
3. Check out send-to-node from debug-js branch
4. Run ./debug.sh in send-to-node (this creates a chat schema and adds a chat document with two updates, materialization seems to work normally here)
5. Go back to shirokuma project, run node ./debug.js here (tested in NodeJS v17)
6. Check GraphQl playground: The document should arrive at message value 3, run step 5 a couple of times and compare, sometimes its 1, sometimes its 2, sometimes its 3

[adzialocha]

The difference between send-to-node and shirokuma is that the latter caches the next entry arguments and might do "faster" requests then send-to-node. I wonder if that time difference creates the crucial race condition.

[adzialocha]

The entries and operations sent by debug.js look like that (hashes vary in each run), should be all fine:

1. CREATE

Entry:

{
  logId: '0',
  seqNum: '1',
  backlink: null,
  skiplink: null
}

Operation:

[
  1,
  0,
  "chat_002009a6721c3015eb87a7b941e5d54183b7bd209c72dec05af234ede47dd4772f35",
  {
    "message": "1"
  }
]

2. UPDATE

Entry:

{
  logId: '0',
  seqNum: '2',
  backlink: '0020d089767fea4a13d8c5972fdabe8105b46d5da9da2bedef0c64b506d6a535b38e',
  skiplink: null
}

Operation:

[
  1,
  1,
  "chat_002009a6721c3015eb87a7b941e5d54183b7bd209c72dec05af234ede47dd4772f35",
  ["0020d089767fea4a13d8c5972fdabe8105b46d5da9da2bedef0c64b506d6a535b38e"],
  {
    "message": "2"
  }
]

3. UPDATE

Entry:

{
  logId: '0',
  seqNum: '3',
  backlink: '00201089cea1f8c547f269dd490d9faae650a41dabfa74ce700cad0dad49ed7b58a8',
  skiplink: null
}

Operation:

[
  1,
  1,
  "chat_002009a6721c3015eb87a7b941e5d54183b7bd209c72dec05af234ede47dd4772f35",
  ["00201089cea1f8c547f269dd490d9faae650a41dabfa74ce700cad0dad49ed7b58a8"],
  {
    "message": "3"
  }
]

[adzialocha]

aquadoggo logs looking normal as well, just not showing the expected updates (sometimes):

[2023-02-28T11:24:02Z INFO  aquadoggo::manager] Start materializer service
[2023-02-28T11:24:03Z INFO  aquadoggo::materializer::worker] Register reduce worker with pool size 16
[2023-02-28T11:24:03Z INFO  aquadoggo::materializer::worker] Register dependency worker with pool size 16
[2023-02-28T11:24:03Z INFO  aquadoggo::materializer::worker] Register schema worker with pool size 16
[2023-02-28T11:24:03Z INFO  aquadoggo::manager] Start replication service
[2023-02-28T11:24:03Z INFO  aquadoggo::manager] Start http service
[2023-02-28T11:24:03Z INFO  aquadoggo::graphql::schema] Subscribing GraphQL manager to schema provider
[2023-02-28T11:24:18Z INFO  aquadoggo::materializer::tasks::reduce] Created <Document dfa4cb>
[2023-02-28T11:24:18Z INFO  aquadoggo::materializer::tasks::reduce] Created <Document 772f35>
[2023-02-28T11:24:18Z INFO  aquadoggo::schema::schema_provider] Updating chat 772f35
[2023-02-28T11:24:18Z INFO  aquadoggo::graphql::schema] Changed schema chat 772f35, rebuilding GraphQL API
[2023-02-28T11:24:18Z INFO  aquadoggo::materializer::tasks::reduce] Created <Document 6a6283>
[2023-02-28T11:24:18Z INFO  aquadoggo::materializer::tasks::reduce] Updated <Document 6a6283> latest view a99d81
[2023-02-28T11:24:19Z INFO  aquadoggo::materializer::tasks::reduce] Updated <Document 6a6283> latest view 794ad6
[2023-02-28T11:24:19Z INFO  aquadoggo::graphql::client::dynamic_query] Handling collection query for chat 772f35
[2023-02-28T11:26:37Z INFO  aquadoggo::materializer::tasks::reduce] Created <Document 5dfa8c>
[2023-02-28T11:26:38Z INFO  aquadoggo::materializer::tasks::reduce] Updated <Document 5dfa8c> latest view a2de79
[2023-02-28T11:26:38Z INFO  aquadoggo::materializer::tasks::reduce] Updated <Document 5dfa8c> latest view cb8d43
[2023-02-28T11:26:40Z INFO  aquadoggo::graphql::client::dynamic_query] Handling collection query for chat 772f35
[2023-02-28T11:26:42Z INFO  aquadoggo::materializer::tasks::reduce] Created <Document 35b38e>
[2023-02-28T11:26:43Z INFO  aquadoggo::graphql::client::dynamic_query] Handling collection query for chat 772f35
[2023-02-28T11:39:54Z INFO  aquadoggo::materializer::tasks::reduce] Created <Document 996bb5>
[2023-02-28T11:39:54Z INFO  aquadoggo::materializer::tasks::reduce] Updated <Document 996bb5> latest view d0e60d
[2023-02-28T11:39:55Z INFO  aquadoggo::graphql::client::dynamic_query] Handling collection query for chat 772f35

[adzialocha]

My theory is that the UPDATEs sometimes arrive on the node while the CREATE operation is being worked on. They unexpectedly do not get rescheduled / get lost after the creation of the document succeeded.

Our task queue logic exists exactly for the reason to account for such out-of-order events (actually not for performance reasons primarily as one might think 😝), so I assume something is fishy here.

[sandreae]

Unfortunately, i can't reproduce this locally.... thanks for the nice bug reproduction steps though, was a pleasure trying 🤣

[adzialocha]

Sending a delayed (2,5 seconds) operation as a third UPDATE (setting message to 4) makes the whole document arrive at the correct value (4):

await new Promise((resolve) => {
  setTimeout(resolve, 2500);
});

await message.update({
  message: '4',
});

[adzialocha]

Running the tests against this fix #283 makes the results "better" but doesn't fix the problem. More values converge to the right final value, but still there are some false ones.