Origin: Transaction error investigation

[mikeshultz]

Franck saw a failed transaction and figure it should be looked at.

https://etherscan.io/tx/0x7b90a510928fb545ab83b4905bca7c44c5ef184f05ffa87ab9d86b2abc5f842c

0x474fa4940000000000000000000000008ac16c08105de55a02e2b7462b1eec6085fa4d860000000000000000000000000000000000000000000000000000000000000080000000000000000000000000ef104523f3829b9f0b0f6d2d52f49f76f8655a9100000000000000000000000000000000000000000000000000000000000001000000000000000000000000000000000000000000000000000000000000000041795b99f3472de47bc780b86866e02ac0fca413108148d1e88fef933dedd6524350e45ef13538ad242156c271ce5e7b21c0df073743c50f6911f784a437de4dc31b0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000

It's a tx to a user's proxy that does appear to have existed at the time of the tx. The call was to forward(address to, bytes sign, address signer, bytes data). Decoded, the call arguments are:

to: 0x8ac16c08105de55a02e2b7462b1eec6085fa4d86 (IdentityEvents)
sign: 795b99f3472de47bc780b86866e02ac0fca413108148d1e88fef933dedd6524350e45ef13538ad242156c271ce5e7b21c0df073743c50f6911f784a437de4dc31b
signer: 0xef104523f3829b9f0b0f6d2d52f49f76f8655a91
data: a30749df6f96a21e0a377a3ea466e68f3b675051d8543619869e94eb55a01f8d53786eae

The forwarded call decodes to:

emitIdentityUpdated(QmVrFBfyoKoy85KLz3FAfBYqNuGZz58DBmpadCvLHxM47P)

I haven't tried to verify the signature yet. A failed signature is my first guess as to why this TX failed. Perhaps someone is just poking at it to see what it does?

Also curious how @franckc came across this?

cc @nick

[franckc]

Thanks @mikeshultz for looking into this.

I noticed the issue by looking at the transactions from one of the relayer hot wallet account on etherscan: https://etherscan.io/txs?a=0x9629f3998d08a7bc479451be450e897e3240b2b2

Eyeballing the data, it looks like about 5% of transactions have this issue.

[mikeshultz]

cc @DanielVF

[DanielVF]

In looking at the remix debugging, I think I'm seeing the signature checking fail. (I see the message signature on the stack shortly before the revert)

In looking at the timeline of transactions on this particular user, I notice that the failing transactions seem to always be during times that many updates are being sent. (One of the failures was only a block apart from a previous successful update)

I've checked a few users and the failures always seem to be later transactions in a burst/pair of rapid updates.

Our signature generating and checking uses a nonce counter stored in the contract.

return keccak256(abi.encodePacked(signer, to, value, data, nonce[signer]));

I'm guessing these failures are due to the dapp side signing transactions with an already used nonce value.

https://github.com/OriginProtocol/origin/blob/a361c6fbcd44cddfac0de2a5efe21940bb686d7c/packages/graphql/src/mutations/_relayer.js#L14-L20

It looks to me like our current code will create these failures by using an old nonce value if another transaction is being created before the previous transaction has round-tripped through the relayer, been mined, and made it to the eth-nodes that we are querying.

It might be nice if we could pass and log the nonce used by the client to the server.

Beyond that, we'd probably need to do actual nonce tracking on the client when generating transactions, and not solely depend on reading it from the client. This quickly gets gnarly and can go very wrong.

[mikeshultz]

Great work, @DanielVF. I think the client should have some level of nonce tracking, but I don't think that's the primary issue here. In this case, both the client and the relayer will be getting the wrong nonce. Most of these are probably due to the user having a pending transaction already and the nonce not yet being updated in the proxy contract. So the nonce that the client and relayer get back from the contract is old by the time the tx gets to the proxy contract.

Was hoping it wasn't going to become necessary, but between this and talk about "batching" or waiting to send identity updates to make sure we get the final one, it looks like relayer is going to need some level of pending transaction introspection into the purse...

Might be as simple as only accepting one tx per proxy contract at any one time, replacing if it's the same destination contract+method, and refusing the rest. Preflight requests could be refused by relayer so the client knows there's a pending out as well and alert the user accordingly.

Or we can get fancy about it and manage the proxy nonce, but maybe that's a long-term goal with a lot of complexity.

EDIT: Also, how did you get that timeline graph? That's pretty sweet.

[DanielVF]

We've got a whole lot of power in that the client can actually talk to the relayer. Probably the main thing going for us here. Otherwise it's a nest of dragons.

I'm wanting a log on the server of the nonces used, so we can debug nonce issues in the future. The nonce isn't recoverable from the tx input. (unless I'm really missing something)

Heh, my timeline graph is just a csv export from etherscan, scatterplotted into Numbers, and then I photoshopped the color of the bad transactions and moved them down to the same line. :)

[mikeshultz]

Today, I'm going to put together a short term solution that prevents users from having more than one pending transaction per account. I agree we'll probably need something more robust in the future. But for now, the dapp only supports one tx at a time, and we need something to at least prevent money from being wasted.

If the optimistic UI starts getting put together, we'll need to discuss this further and come up with a long-term solution.

[mikeshultz]

Looked at another tx that just failed earlier today(0x3dafbe85fdeb9201ef69923377c0b3b83e9d9324cdb3670f925fb4c54ef92239). I can confirm it's signature failure. The revert string is in memory("signer-not-owner").

The signature is valid with nonce 2, and the nonce at the time of the tx(block number 8117703) was 3. The fix I added yesterday apparently had no effect on this issue for some reason. As far as the relayer is concerned, there was no pending transactions for this user at the time. There don't appear to be any duplicate transactions, but there does appear to be multiple relatively close together(~30s).

I don't see any transactions that were stopped by my pending check, either. So, gonna test that a bit more to double check that it's working.

[DanielVF]

One of the fun things we can do is diff the actual block time vs the relayer DB record created time to get a range that the TX was in the system.

[mikeshultz]

Turns out, the pending check had a bug. Got a fix in and will deploy shortly.

[DanielVF]

Looks like we can close this - I don't see a single failure like this on the 0x962 worker since you pushed this fix.

[mikeshultz]

A set of rapid fire transactions seem to have triggered this again.

1) Dapp pulls nonce 1 from state
2) Dapp builds tx with nonce 1, signs, and sends it to the relayer
3) Relayer pulls nonce 1 from state and verifies
4) Relayer sends tx, shows it mined, removes it from pending
5) Dapp pulls nonce 1 from out-of-date state
6) Dapp builds tx with nonce 1, signs, and sends it to the relayer
7) Relayer pulls nonce 1 from out-of-date state and verifies the signature
8) Relayer sends tx, tx fails because of nonce re-use and reverts

This has to happen within the small window of the transaction being mined, relayer seeing that transaction as mined, and the proxy contract state not yet being updated on the provider's systems.

This is the 3 relayer transactions that caused this:

1st: 0x7fd9329293e45402fcc8d14320bd6e2ef454c3ffd1d502324aec951db2a8a5ff
2dn: 0xa3ef5412e24ade7f959479ef75ec7b0c9e104ec14f908a1da1c61246ead25d48
3rd: 0xfde9e1e88af71d1b353d3d18e0cfdd7c22b287f5daf4d0c99e4ced5e7536c393(failed)

Will have to add IdentityProxy nonce sanity check to the relayer... if provided_nonce > last_known_nonce: go(); else: throw().

[mikeshultz]

PR #2742 adds a defensive check to try and prevent this by using a little internal nonce tracking. This should take care of this edge case, while trying to keep complexity down. Currently in dev, will probably deploy this afternoon.