bug: sync stopped in the new reliable integrations because of an ordering issue

[andreabadesso]

Summary

Sync stopped again while handling event 5760219 with the following logs (numbered by me):

1 - 2023-11-14T15:37:50.390Z [wallet-service-daemon][debug]: Received VERTEX_METADATA_CHANGED: 5760219 from socket.
2 - 2023-11-14T15:37:50.391Z [wallet-service-daemon][info]: Processing event: "FULLNODE_EVENT"
3 - 2023-11-14T15:37:50.391Z [wallet-service-daemon][info]: Transitioned to {"CONNECTED":{"handlingMetadataChanged":"detectingDiff"}}
4 - 2023-11-14T15:37:50.393Z [wallet-service-daemon][info]: Processing event: "done.invoke.SyncMachine.CONNECTED.handlingMetadataChanged.detectingDiff:invocation[0]"
5 - 2023-11-14T15:37:50.393Z [wallet-service-daemon][info]: Transitioned to {"CONNECTED":"handlingUnvoidedTx"}
6 - 2023-11-14T15:37:50.395Z [wallet-service-daemon][debug]: Tx 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81 got unvoided, cleaning up the database.
7 - 2023-11-14T15:37:50.398Z [wallet-service-daemon][debug]: Unvoided tx 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81
8 - 2023-11-14T15:37:50.404Z [wallet-service-daemon][info]: Processing event: "done.invoke.handlingUnvoidedTx:invocation[0]"
9 - 2023-11-14T15:37:50.404Z [wallet-service-daemon][info]: Transitioned to {"CONNECTED":"handlingVertexAccepted"}
10 - 2023-11-14T15:37:50.408Z [wallet-service-daemon][debug]: Will add the tx with height
11 - 2023-11-14T15:37:50.424Z [wallet-service-daemon][error]: BIGINT UNSIGNED value is out of range in '(`hathor3`.`address_balance`.`unlocked_balance` + -(500))'
12 - 2023-11-14T15:37:50.429Z [wallet-service-daemon][error]: error.platform.handlingVertexAccepted:invocation[0]
13 - 2023-11-14T15:37:50.429Z [wallet-service-daemon][info]: Processing event: "error.platform.handlingVertexAccepted:invocation[0]"
14 - 2023-11-14T15:37:50.429Z [wallet-service-daemon][info]: Transitioned to "ERROR"

Five-whys

Why?

As we can see from the logs, the event is "unvoiding" the transaction 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81

The way we're handling "unvoided" transaction events is to basically remove all traces (and subtracting or adding balances from all involved addresses) and then re-adding the transaction by using the data that came in the event

As we can see on line 7, the service removed the transaction successfully and then transitioned to handlingVertexAccepted to re-add it to database

When it was trying to add it (on line 10), we got a balance error because the resulting unlocked_balance was lower than 0

Querying the database, we can see that indeed the balance is indeed zero after removing all traces from the transaction ***:

mysql> SELECT address, unlocked_balance FROM address_balance WHERE address = 'HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh';
+------------------------------------+------------------+
| address                            | unlocked_balance |
+------------------------------------+------------------+
| HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh |                0 |
+------------------------------------+------------------+
1 row in set (0.00 sec)

So when 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81 attempts to spend 5 HTR from it, it will yield exactly the error from our logs

Why?

I queried the address_tx_history for this address to check the history of transactions for this address:

mysql> SELECT * FROM address_tx_history WHERE address = 'HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh';
+------------------------------------+------------------------------------------------------------------+----------+---------+------------+--------+
| address                            | tx_id                                                            | token_id | balance | timestamp  | voided |
+------------------------------------+------------------------------------------------------------------+----------+---------+------------+--------+
| HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh | 0000076da38a8a9077b84e472dbaf9cc2c1d1da6903916b57ad3b142f3653c52 | 00       |    -500 | 1698107697 |      0 |
| HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh | 0000088f2dac480d490b05bc1ad95c64688e41ff6212c56fad6227d5ee186c7d | 00       |     500 | 1698107611 |      0 |
+------------------------------------+------------------------------------------------------------------+----------+---------+------------+--------+
2 rows in set (0.00 sec)

As we can see, there are only two transactions for this address, it receives the utxo spent on 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81 adding 5 HTR to the balance and spends it later on on 0000076da38a8a9077b84e472dbaf9cc2c1d1da6903916b57ad3b142f3653c52, removing 5 HTR from it

I checked this second transaction on the fullnode, and found out that it spends exactly the same utxo that our unspent tx spends, causing a double-spend, but has a smaller acc weight (63.89 vs over 65.12)

So our unspent transaction should be the one on our database and this second one should have been voided

Why?

I checked the event history manually by using the HTTP API starting at one event before our event (5760219) and apparently what happened was an event ordering issue

I still need to download the entire event database to understand the complete chronology, but apparently what happened here was this, in a chronological way:

1. Transaction 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81 gets inserted into database, spending funds from HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh on event XXX
2. Transaction 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81 gets voided, re-adding funds to HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh on event XXX
3. Transaction 0000076da38a8a9077b84e472dbaf9cc2c1d1da6903916b57ad3b142f3653c52 gets inserted into database, spending funds from HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh

This is the state of the database before our event (5760219) arrives, now that's what happens:

4. Event 5760219 arrives, "unvoiding" transaction 0000407a55615a5dc909d534365d36c226d98f3ba2e0210d96f2d606480fde81, causing it to spend funds from HBtTjEvTeL5QN5JfvDTShC6SxaoKsvZRZh, but since 0000076da38a8a9077b84e472dbaf9cc2c1d1da6903916b57ad3b142f3653c52 was not yet voided, the address has a zero balance and thus causing our invalid balance error

Following on the events using the HTTP API, we can see that the very next event (5760220) voids the transaction 0000076da38a8a9077b84e472dbaf9cc2c1d1da6903916b57ad3b142f3653c52

So this is an ordering issue, the sync daemon by itself apparently is unable to handle this event order, we need to think on a solution in the fullnode

***: This is an issue, we should have rolled back the entire operation, this should also be fixed

Solution

This was fixed by @glevco in this PR by changing the event ordering to send the voided transaction first

[andreabadesso]

Reviewers:
@glevco @r4mmer

[glevco]

LGTM 👍

[r4mmer]

LGTM ✅