omgnetwork/elixir-omg

Utxo not found when attempting transaction with some utxos

nicholasmueller opened this issue · 10 comments

nicholasmueller commented

Some utxos returned from account.get_utxos cause utxo_not_found error when creating transactions with them. observed on mainnet.

account.get_utxos returns these 2 utxos that i want to merge:

amount: 10000000000000000
blknum: 83000
creating_txhash: "0x447ec5ec92a647b1d6947c2faf9a575486e5811e4c0576f3d4015722124573b2"
currency: "0xd26114cd6ee289accf82350c8d8487fedb8a0c07"
inserted_at: "2020-06-18T09:40:06Z"
oindex: 1
otype: 1
owner: "0x0339b1187101bce651ee6215c9c9b34b560873c5"
spending_txhash: null
txindex: 0
updated_at: "2020-06-18T09:40:06Z"
utxo_pos: 83000000000001

amount: 3830922229089327600
blknum: 3692000
creating_txhash: "0xb0bcd3164ef339c63fadbf5e0fbd457470ba8c02ef980e2d5f32617b569cbcaf"
currency: "0xd26114cd6ee289accf82350c8d8487fedb8a0c07"
inserted_at: "2020-10-29T08:06:19Z"
oindex: 0
otype: 1
owner: "0x0339b1187101bce651ee6215c9c9b34b560873c5"
spending_txhash: null
txindex: 0
updated_at: "2020-10-29T08:06:19Z"
utxo_pos: 3692000000000000

i create a merge transaction using these 2 utxos and form this typed data:

txType:1
input0:
  blknum:83000
  txindex:0
  oindex:1
input1:
  blknum:3692000
  txindex:0
  oindex:0
input2:
  blknum:0
  txindex:0
  oindex:0
input3:
  blknum:0
  txindex:0
  oindex:0
output0:
  outputType:1
  outputGuard:0x0339B1187101bCE651EE6215C9c9b34B560873c5
  currency:0xd26114cd6ee289accf82350c8d8487fedb8a0c07
  amount:3840922229089327700
output1:
  outputType:0
  outputGuard:0x0000000000000000000000000000000000000000
  currency:0x0000000000000000000000000000000000000000
  amount:0
output2:
  outputType:0
  outputGuard:0x0000000000000000000000000000000000000000
  currency:0x0000000000000000000000000000000000000000
  amount: 0
output3:
  outputType: 0
  outputGuard: 0x0000000000000000000000000000000000000000
  currency: 0x0000000000000000000000000000000000000000
  amount: 0
  txData: 0
metadata: 0x0000000000000000000000000000000000000000004d65726765205554584f73

I sign and submit the transaction calling transaction.submit and get back:

code: "submit:utxo_not_found"
description: null
object: "error

I suspect the first utxo is the erroneous one. for some reason I cannot spend this utxo.

nicholasmueller commented

The suspected erroneous utxo at pos 83000000000001 was already exited:
https://etherscan.io/tx/0xec704671a1ddb5358f6fcf4441d9af5c130dda3f8157dd45f6c066bc9826f915

unnawut commented

I can confirm a similar situation for me from the demo.

Running:

curl -s -X POST https://watcher-info.mainnet.v1.omg.network/account.get_utxos \
-H "Content-Type: application/json" \
-d '{
  "address": "0xf876154263cF61E15e84695096cFdCb5ceEd8D86"
}' \
-w "\n" | jq

Gives:

{
  "data": [
    {
      "amount": 1e+16,
      "blknum": 238000,
      "creating_txhash": "0x8150a5c52536df28622ff4b8745a164c05fb7ad60cdc1ce531b77d42ae5ab802",
      "currency": "0xd26114cd6ee289accf82350c8d8487fedb8a0c07",
      "inserted_at": "2020-06-18T10:06:15Z",
      "oindex": 1,
      "otype": 1,
      "owner": "0xf876154263cf61e15e84695096cfdcb5ceed8d86",
      "spending_txhash": null,
      "txindex": 0,
      "updated_at": "2020-06-18T10:06:15Z",
      "utxo_pos": 238000000000001
    },
    {
      "amount": 2146714250335326500,
      "blknum": 239000,
      "creating_txhash": "0xfe89db8a1ae9aa749122cfd85afb0d04fced2bd13068cf21a8d60051ffdd831c",
      "currency": "0xd26114cd6ee289accf82350c8d8487fedb8a0c07",
      "inserted_at": "2020-06-18T10:06:31Z",
      "oindex": 1,
      "otype": 1,
      "owner": "0xf876154263cf61e15e84695096cfdcb5ceed8d86",
      "spending_txhash": null,
      "txindex": 0,
      "updated_at": "2020-06-18T10:06:31Z",
      "utxo_pos": 239000000000001
    },
    ...
    {
      "amount": 2039756824914914600,
      "blknum": 3481000,
      "creating_txhash": "0xad5aa42ecee6ec70d38957619a47b12fc90497c2a20b54c5fe314d446644fd9c",
      "currency": "0xd26114cd6ee289accf82350c8d8487fedb8a0c07",
      "inserted_at": "2020-10-02T11:17:34Z",
      "oindex": 0,
      "otype": 1,
      "owner": "0xf876154263cf61e15e84695096cfdcb5ceed8d86",
      "spending_txhash": null,
      "txindex": 0,
      "updated_at": "2020-10-02T11:17:34Z",
      "utxo_pos": 3481000000000000
    },
    ...
}

Running:

curl -s -X POST https://watcher-info.mainnet.v1.omg.network/account.get_exitable_utxos \
-H "Content-Type: application/json" \
-d '{
  "address": "0xf876154263cF61E15e84695096cFdCb5ceEd8D86"
}' \
-w "\n" | jq

Gives: (note that get_exitable_utxos does not return utxo 239000000000001)

{
  "data": [
    {
      "amount": 1e+16,
      "blknum": 238000,
      "currency": "0xd26114cd6ee289accf82350c8d8487fedb8a0c07",
      "oindex": 1,
      "otype": 1,
      "owner": "0xf876154263cf61e15e84695096cfdcb5ceed8d86",
      "txindex": 0,
      "utxo_pos": 238000000000001
    },
    {
      "amount": 2039756824914914600,
      "blknum": 3481000,
      "currency": "0xd26114cd6ee289accf82350c8d8487fedb8a0c07",
      "oindex": 0,
      "otype": 1,
      "owner": "0xf876154263cf61e15e84695096cfdcb5ceed8d86",
      "txindex": 0,
      "utxo_pos": 3481000000000000
    },
    ...
}

Metamask message:

Message
  txType: 1
  input0:
    blknum: 239000
    txindex: 0
    oindex: 1
  input1:
    blknum: 0
    txindex: 0
    oindex: 0
  input2:
    blknum: 0
    txindex: 0
    oindex: 0
  input3:
    blknum: 0
    txindex: 0
    oindex: 0
  output0:
    outputType: 1
    outputGuard: 0xf876154263cF61E15e84695096cFdCb5ceEd8D86
    currency: 0xd26114cd6ee289accf82350c8d8487fedb8a0c07
    amount: 1043735294971103340
  output1:
    outputType: 1
    outputGuard: 0xf876154263cF61E15e84695096cFdCb5ceEd8D86
    currency: 0xd26114cd6ee289accf82350c8d8487fedb8a0c07
    amount: 1000000000000000000
  output2:
    outputType: 0
    outputGuard: 0x0000000000000000000000000000000000000000
    currency: 0x0000000000000000000000000000000000000000
    amount: 0
  output3:
    outputType: 0
    outputGuard: 0x0000000000000000000000000000000000000000
    currency: 0x0000000000000000000000000000000000000000
    amount: 0
  txData: 0
  metadata: 0x00000000000000000000

The utxo was already exited: https://etherscan.io/tx/0x316e2d1c7be7b25f4e9b8f14f6a64aef008a4cde53d8d971398efa6ce71a6d87

pnowosie commented

Regarding the issue - @InoMurko has nailed the root cause already in the slack thread.
Watcher-Info does not impose any ordering on processing Ethereum's events. It's basing on Watcher which imposes ordering of its Ethereum Event Processors so during the normal operation Watcher-Info receives events in the right order. In the rare cases it's receives ExitStarted event before the block which produces exited utxo is processed.
In such case W-I does nothing, so we don't get awared even by inspecting the logs.

How it looks now

In the database in TxOutput records can relate to EthEvents through many-to-many relation. Such events can create utxos (deposits) or spen them (exits both std & in-flight).

To make things even more complicated artificial key is used in the relation for txoutput (derrived from utxo position).

The mentioned many-to-many relation defines foreign key constraints on both tables (txoutput & ethevents) which effectively requires both records existence before a link can be created.

Solution draft

1. Quick fix

  • Precompute and fill txoutput.child_chain_utxohash for every output added to the DB. We can do this as it depends only on output's position.
  • Delete foreign key constraint between txoutputs and ethevents_txoutputs
  • Inserting the event which corresponds to the output (deposit or exit) and manualy create a link in ethevents_txoutputs table without checking the outpout existance. (can be done in plain SQL, it's probably against ecto philosophy).

All remaining code should stay unchanged.

2. a little redesign

There is no point to push it further as the Info-Watcher is going to transform into something else...

InoMurko commented

Maybe we can simplify this by:
making the exit processor consumer crash, if there's no utxo to exit?

and we can modify the sync supervisor event listeners to include these consumers as callbacks, effectevely bypassing (not using) OMG Bus for these events. This means that event listeners would retry until they get the event both into rocksdb and into postgres. but with elixir apply/3, we can make sure that there's no coupling with watcher security and watcher info

InoMurko commented

an example of exit started would look like:
this would go from:

get_events_callback: &EthereumEventAggregator.exit_started/2,

into:

get_events_callback: fn -> 
case Code.ensure_loaded?(OMG.WatcherInfo.ExitConsumer) do
false ->&Watcher.ExitProcessor.new_exits/1
true ->
{&OMG.WatcherInfo.ExitConsumer.exit_started/1, &Watcher.ExitProcessor.new_exits/1}
end

And the processing part:

case callbacks.process_events_callback do
{watcher_info_callback, watcher_security_callback} ->
  :ok = watcher_info_callback.(events) # you need to make sure ExitConsumer REALLY DIES if it can't insert an exit!!!!
  {:ok, db_updates_from_callback} = watcher_security_callback.(events)
  :ok = OMG.DB.multi_update(db_updates ++ db_updates_from_callback)
watcher_security_callback -> 
  {:ok, db_updates_from_callback} = watcher_security_callback.(events)
  :ok = OMG.DB.multi_update(db_updates ++ db_updates_from_callback)
end
# this is not needed anymore :ok = publish_events(events)

so if an exit arrives before a block is processed, the exit would keep on retrying to apply the exit (because the callbacks would kill the relevant ethereum event listener, and root chain coordinator would not let him move forward.

pnowosie commented

Thanks @InoMurko - I like the idea! 🙏

I've investigate IFE processing by the Info-Watcher's ExitConsumer. According to #1496 (this comment) there are 3 events handled

  • InFlightExitStarted - passes a list of input's utxo positions - we can take for granted they exist in txouputs or let the service die abruptly otherwise,
  • InFlightExitOutputWithdrawn - passes a list of utxo positions spent by Security-Watcher - they have to exist or service will die,
  • InFlightTxOutputPiggybacked - tricky part, passes {txhash, oindex} of in-flight transaction's output. Transaction might be eventually sent to ch-ch - so output might appear but without guarantee. We cannot stop EvenListener from progressing.

The last point might seem to be not covered, but if the ife-tx was processed by the child-chain, it's output exists in the utxo set. So Security-Watcher will include its position in InFlightExitOutputWithdrawn event. It will be late (after ife process time) but better than nothing.

⚠️ Note: event InFlightExitIOputProcessed was renamed later to InFlightExitOutputWithdrawn

InoMurko commented

fyi, there's another way, to achieve a similar result:
which is effectevely what @mederic-p has done for block processing:

{OMG.WatcherInfo.BlockApplicationConsumer, []},
{OMG.WatcherInfo.PendingBlockProcessor, [processing_interval: Configuration.pending_block_processing_interval()]},
{OMG.WatcherInfo.PendingBlockQueueLengthChecker, [check_interval: Configuration.block_queue_check_interval()]},

which is basically a queue in front of the actually block processing.
But you need to be aware, that in this case, a things can also go wrong. Publishing messages and storing them in the queue is done async - while the message is being put in the queue - if watcher info as a service exits, rocksdb and postgres can still go out of sync. Chances are - tho not huge.

So, the only way how to achieve consistency is to make sure both callbacks (into rocksdb and postgres) succeed, if one of them doesn't - you need a rollback.

pnowosie commented

rocksdb and postgres can still go out of sync. Chances are - tho not huge.

yeah, sounds the same as the chances we process exit first then block :) I think it'd be better to go with callback proposition (there are no issues regarding event listeners - so looks as a safer approach)

InoMurko commented

this needs to be updated as it's not correct. Watcher info callbacks need to be tuples, you cannot reference to a function because it would need to be there at compilation (release). And it wouldn't be possible when creating a watcher security release. Hence, the use of :erlang.apply/3 -> :ok = apply(module, function, [events])
#1760 (comment)

UPDATE:
an example of exit started would look like:
this would go from:

get_events_callback: &EthereumEventAggregator.exit_started/2,

into:

get_events_callback: fn - 
case Code.ensure_loaded?(OMG.WatcherInfo.ExitConsumer) do
false ->&Watcher.ExitProcessor.new_exits/1
true ->
{{OMG.WatcherInfo.ExitConsumer, :exit_started}, &Watcher.ExitProcessor.new_exits/1}
end

And the processing part:

case callbacks.process_events_callback do
{{module, function}, watcher_security_callback} ->
  :ok = apply(module, function, [events]) # you need to make sure ExitConsumer REALLY DIES if it can't insert an exit!!!!
  {:ok, db_updates_from_callback} = watcher_security_callback.(events)
  :ok = OMG.DB.multi_update(db_updates ++ db_updates_from_callback)
watcher_security_callback - 
  {:ok, db_updates_from_callback} = watcher_security_callback.(events)
  :ok = OMG.DB.multi_update(db_updates ++ db_updates_from_callback)
end
# this is not needed anymore :ok = publish_events(events)

so if an exit arrives before a block is processed, the exit would keep on retrying to apply the exit (because the callbacks would kill the relevant ethereum event listener, and root chain coordinator would not let him move forward.

InoMurko commented

Another thing we discussed on Slack:

:ok = apply(module, function, [events]) # you need to make sure ExitConsumer REALLY DIES if it can't insert an exit!!!!
{:ok, db_updates_from_callback} = watcher_security_callback.(events)
:ok = OMG.DB.multi_update(db_updates ++ db_updates_from_callback)

If you write to PG first and then to RocksDB, you need to provide a rollback for postgres write for the events you're pushing in.

If you write to RocksDB first and then to Postgres, you need to provide a rollback for RocksDB write for the events you're pushing in.

That's because you need to keep two different databases in sync! Artificial transaction between two databases he he.