A transaction that will normally fail to execute due to a uniqueness violation, if submitted as a deferred transaction will partially execute instead of failing entirely as expected

[acoutts]

When submitting a transaction that will cause a uniqueness constraint violation, it will fail immediately when submitting the transaction through cleos as expected. But submitting the exact same transaction as a deferred transaction causes some of the actions to succeed according to the history plugin and signals from the chain plugin while throwing the uniqueness constraint violation in nodeos:

#   19   2018-11-01T19:47:06.000     chintailease::prepare => chintailease  cc941cbb... {"memo":"useraccount2|1|30|0.1000|0|0.5000|cqfcymm6p2"}...
#   20   2018-11-01T19:47:06.000     eosio.token::transfer => chintailease  cc941cbb... {"from":"useraccount2","to":"chintailease","quantity":"3.000...
#   21   2018-11-01T19:47:06.000    chintailease::activate => chintailease  cc941cbb... {"memo":"useraccount2|1|30|0.1000|0|0.5000|cqfcymm6p2"}...
#   22   2018-11-01T19:47:42.000  chintailease::processpool => chintailease  555148f7... "00"...
#   23   2018-11-01T19:48:57.000  chintailease::processpool => chintailease  9828235f... "00"...
#   24   2018-11-01T19:50:12.000  chintailease::processpool => chintailease  d4e08b44... "00"...
#   25   2018-11-01T19:51:27.000  chintailease::processpool => chintailease  1467e696... "00"...
#   26   2018-11-01T19:52:42.000  chintailease::processpool => chintailease  1c51d943... "00"...
#   27   2018-11-01T19:53:25.000     chintailease::prepare => chintailease  606788ba... {"memo":"useraccount2|1|30|0.1000|0|0.5000|cqfcymm6p2"}...
#   28   2018-11-01T19:53:57.000  chintailease::processpool => chintailease  0c79cf6a... "00"...

Line 27 is an attempt to submit a duplicate transaction already done in line 19.

I haven't confirmed yet if any contract tables were actually changed or if it's just a bug in the history plugin where it shouldn't have recorded the second transaction attempt at line 27 due to it failing for uniqueness constraint violation.

Here is the nodeos output including some tags from the different signals in the chain plugin showing that the action trace was visible in accepted/applied transaction even though the transaction should have failed:

info  2018-11-01T19:53:24.503 thread-0  watcher_plugin.cpp:336        on_accepted_transact ] [on_accepted_transaction] meta: {"expiration":"2018-11-01T19:53:24","ref_block_num":1975,"ref_block_prefix":1084638139,"max_net_usage_words":0,"max_cpu_usage_ms":0,"delay_sec":30,"context_free_actions":[],"actions":[{"account":"chintailease","name":"prepare","authorization":[{"actor":"useraccount2","permission":"active"}],"data":"2c757365726163636f756e74327c317c33307c302e313030307c307c302e353030307c63716663796d6d367032"},{"account":"eosio.token","name":"transfer","authorization":[{"actor":"useraccount2","permission":"active"}],"data":"20f2d414217315d6a0b051d1993c5d43307500000000000004454f53000000002c757365726163636f756e74327c317c33307c302e313030307c307c302e353030307c63716663796d6d367032"},{"account":"chintailease","name":"activate","authorization":[{"actor":"useraccount2","permission":"active"}],"data":"2c757365726163636f756e74327c317c33307c302e313030307c307c302e353030307c63716663796d6d367032"}],"transaction_extensions":[],"signatures":[],"context_free_data":[]}
info  2018-11-01T19:53:24.503 thread-0  watcher_plugin.cpp:178        on_applied_tx        ] [on_applied_transaction] trace: {"id":"606788ba6d9d55233fbec6f9d1d69fe5d8bf1d5d2f0cf2dc1f052200389dab58","block_num":2037,"block_time":"2018-11-01T19:53:25.000","receipt":{"status":"hard_fail","cpu_usage_us":564,"net_usage_words":0},"elapsed":565,"net_usage":0,"scheduled":true,"action_traces":[{"receipt":{"receiver":"chintailease","act_digest":"88794f3bda96de6b13dee7f3d4bf7f1517239045856efb52bbc6ae7f46311646","global_sequence":0,"recv_sequence":0,"auth_sequence":[],"code_sequence":0,"abi_sequence":0},"act":{"account":"chintailease","name":"prepare","authorization":[{"actor":"useraccount2","permission":"active"}],"data":"2c757365726163636f756e74327c317c33307c302e313030307c307c302e353030307c63716663796d6d367032"},"context_free":false,"elapsed":526,"console":"","trx_id":"606788ba6d9d55233fbec6f9d1d69fe5d8bf1d5d2f0cf2dc1f052200389dab58","block_num":2037,"block_time":"2018-11-01T19:53:25.000","account_ram_deltas":[],"except":{"code":13,"name":"St9exception","message":"could not insert object, most likely a uniqueness constraint was violated","stack":[{"context":{"level":"warn","file":"wavm.cpp","line":73,"method":"call","hostname":"","thread_name":"thread-0","timestamp":"2018-11-01T19:53:24.503"},"format":"${what}: ","data":{"what":"could not insert object, most likely a uniqueness constraint was violated"}},{"context":{"level":"warn","file":"apply_context.cpp","line":72,"method":"exec_one","hostname":"","thread_name":"thread-0","timestamp":"2018-11-01T19:53:24.503"},"format":"pending console output: ${console}","data":{"console":""}}]},"inline_traces":[]}],"failed_dtrx_trace":null,"except":{"code":13,"name":"St9exception","message":"could not insert object, most likely a uniqueness constraint was violated","stack":[{"context":{"level":"warn","file":"wavm.cpp","line":73,"method":"call","hostname":"","thread_name":"thread-0","timestamp":"2018-11-01T19:53:24.503"},"format":"${what}: ","data":{"what":"could not insert object, most likely a uniqueness constraint was violated"}},{"context":{"level":"warn","file":"apply_context.cpp","line":72,"method":"exec_one","hostname":"","thread_name":"thread-0","timestamp":"2018-11-01T19:53:24.503"},"format":"pending console output: ${console}","data":{"console":""}}]}}
info  2018-11-01T19:53:24.503 thread-0  watcher_plugin.cpp:169        on_action_trace      ] [on_action_trace] [606788ba6d9d55233fbec6f9d1d69fe5d8bf1d5d2f0cf2dc1f052200389dab58] Added trace to queue: prepare | To: chintailease | From: useraccount2 | Data: {"memo":"useraccount2|1|30|0.1000|0|0.5000|cqfcymm6p2"}
info  2018-11-01T19:53:25.000 thread-0  watcher_plugin.cpp:328        on_accepted_block_he ] [on_accepted_block_header] block_num: 2037
info  2018-11-01T19:53:25.000 thread-0  watcher_plugin.cpp:256        on_accepted_block    ] [on_accepted_block] block_num: 2037
info  2018-11-01T19:53:25.000 thread-0  watcher_plugin.cpp:280        on_accepted_block    ] [on_accepted_block] block_num: 2037
info  2018-11-01T19:53:25.001 thread-0  watcher_plugin.cpp:281        on_accepted_block    ] [on_accepted_block] Matched TX in accepted block: 606788ba6d9d55233fbec6f9d1d69fe5d8bf1d5d2f0cf2dc1f052200389dab58
info  2018-11-01T19:53:25.001 thread-0  watcher_plugin.cpp:287        on_accepted_block    ] [on_accepted_block] Action queue size after removing item: 0

[tbfleming]

Those look like log entries. Are you getting those results out of the history plugin’s json rpc api?

[tbfleming]

The history plugin relies on chainbase’s undo to clean up garbage results as a side effect of controller’s use of undo.

[acoutts]

The first snippet is output from cleos get actions, the second is log output in nodeos.

[taokayan]

What do you mean by "partially execute"?

[acoutts]

The transaction that was broadcasted had 3 actions in it as shown above (prepare, transfer, activate).

The transaction is designed such that if it would be submitted again as a duplicate then the activate action would try to insert a duplicate row and cause the entire transaction to fail. In the action log above i submitted the same transaction twice - it succeeded the first time as expected but the second time should have failed completely but actually one of the actions were applied according to anything listening on the applied transaction signal such as the history api and my plugin.

The transaction fails as expected when submitted as a normal transaction with nothing applied.

If it’s executed as a deferred transaction then the first action (prepare) emits an applied transaction signal and is saved in the history plugin while the other 2 actions are not applied as expected.

[tbfleming]

I see what happened. The signaling is correct. The way the history plugin relies on undo backfired.

[tbfleming]

Signaling: it’s marked as a hard_fail, something plugins should either filter on or record. Recoding it allows you to see why deferred transactions fail. state_history_plugin records deferred failures.

[tbfleming]

On the postgresql side of things: clients which only care about executed actions will include “where transaction_status=‘executed’”

[tbfleming]

Analysis: the history plugin has a core assumption that it can blindly store traces without any status checking. The idea is that anything it stores will be rolled back by undo when there's a problem.

Problem: controller sometimes does the undo before sending applied_transaction.

Potential fix: the history plugin will have to check for the existence of a transaction receipt. If it's absent or indicates failure then it shouldn't store the trace.

Caution for history plugin users: the history plugin is deprecated. It may have additional unnoticed border cases.

Caution for other plugin authors: even after this fix, the history plugin will still rely on undo, which greatly simplifies its logic. Plugins which store data outside of chainbase have a much higher burden. The history plugin is not suitable as a reference.

[abourget]

Isn't it interesting to have the hard_fail transaction stored somewhere? Otherwise, how can you know some transactions failed? It's the only way a user can grab that info an debug its contract.

Perhaps the user should check for the status?

[abourget]

@acoutts is that on mainnet? if so, would you share the transaction ID?

[tbfleming]

Isn't it interesting to have the hard_fail transaction stored somewhere? Otherwise, how can you know some transactions failed? It's the only way a user can grab that info an debug its contract.

Absolutely. That's what the mongodb and state history plugins do, but only for deferred since those are part of consensus.

The deprecated history plugin won't after this fix.

[acoutts]

@abourget this was just on my local testnet.

[arhag]

Resolved by #6220.