mainnet/ft-burn? fails without clear reason

[perplexedpigmy]

We had ft-burn? failing with u1 error
As per the documentation
"If a non-positive amount is provided to burn, this function returns (err 1). Otherwise, on successfuly burn, it returns (ok true)."

But neither the amount (3,000,000, 000) was negative nor would the action result in the principal having negative number of tokens and a consecutive identical ft-burn? went through without any hiccups

It happened only once, so I am unclear whether it is reproducible or how.

Yet, I would expect, clarity's functions to be predictable, given the same preconditions, yield the same results.

Relevant excerpt of the function calling ft-burn? constants displayed as value

((define-public (burn-tokens (burn-amount uint) (burn-from principal) )
  (begin
    (asserts! (has-role BURNER_ROLE contract-caller) (err u403))
    (print { action: "burn-tokens", burn-amount: burn-amount, burn-from : burn-from  })
    (ft-burn? wrapped-bitcoin burn-amount burn-from)))

[jcnelson]

Hey! Do you remember the value of tokens you tried to burn? If it was 0, then you'll get (err 1).

[perplexedpigmy]

Thanks @jcnelson, it was 3,000,000,000 tokens, issue updated with the information.
The links are for the relevant transactions on mainnet.

[jcnelson]

This might be a glitch in the explorer. On my node, I'm seeing this transaction getting successfully processed.

[jcnelson]

Full transcript of the processing in my node:

DEBG [1672297752.667441] [src/chainstate/stacks/db/transactions.rs:1151] [chains-coordinator-0.0.0.0:20443] Process transaction 22adb4110490fbe380ad3c5891fdb4fefe3a7f44ef35a1f2042da27aa12ee656 (ContractCall)                                                                        
DEBG [1672297752.667541] [clarity/./src/vm/database/clarity_db.rs:1522] [chains-coordinator-0.0.0.0:20443] Fetching account balance, principal: SPF8P53TXE81XMBVXXERTT513R0SV8PYTNNC9TKZ                                                                                                                                     
DEBG [1672297752.670713] [clarity/./src/vm/functions/mod.rs:470] [chains-coordinator-0.0.0.0:20443] (tuple (action "burn tokens") (burn-amount u300000000) (burn-from SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V))                    
INFO [1672297752.671195] [src/chainstate/stacks/db/transactions.rs:895] [chains-coordinator-0.0.0.0:20443] Contract-call successfully processed, contract_name: SP3DX3H4FEYZJZ586MFBS25ZW3HZDMEW92260R2PR.Wrapped-Bitcoin, function_name: burn-tokens, function_args: [u300000000, SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V] return_value: (err u1), cost: ExecutionCost { write_length: 1, write_count: 2, read_length: 10625, read_count: 6, runtime: 22146 }
DEBG [1672297752.671237] [clarity/./src/vm/database/clarity_db.rs:1522] [chains-coordinator-0.0.0.0:20443] Fetching account balance, principal: SPF8P53TXE81XMBVXXERTT513R0SV8PYTNNC9TKZ                                                           
DEBG [1672297752.671523] [clarity/./src/vm/database/clarity_db.rs:1522] [chains-coordinator-0.0.0.0:20443] Fetching account balance, principal: SPF8P53TXE81XMBVXXERTT513R0SV8PYTNNC9TKZ                                                                                                                                       
DEBG [1672297752.671852] [src/chainstate/stacks/index/marf.rs:1067] [chains-coordinator-0.0.0.0:20443] MARF Insert in b40ffa12cd6cdec17a0cf0231bffb40d9271c319a5113e88792a3488765e6c6b: '13c721113c7965a16c53d36d8bcd261bca205bab498fb6164b6e0c256f174eba' = 'deda515d0df05f3904deb34e6642359007e5d192559e3602574aec12e2c488050000000000000000' (...[])                                                                                                                                                                                                                                                                                                       
DEBG [1672297752.671875] [src/chainstate/stacks/index/trie.rs:990] [chains-coordinator-0.0.0.0:20443] Next root hash is 0000000000000000000000000000000000000000000000000000000000000000 (update_skiplist=false)                                                                                                               
DEBG [1672297752.671948] [src/chainstate/stacks/index/marf.rs:1067] [chains-coordinator-0.0.0.0:20443] MARF Insert in b40ffa12cd6cdec17a0cf0231bffb40d9271c319a5113e88792a3488765e6c6b: '79e9c36e8fe2ba07752789d2b70e020dbfaf1e9149a9eaa27f1512ecbe08a526' = 'c5ca3bec28ca7bbd6f6a62173942266a8dc1f93bb060442c07b947a0171da10c0000000000000000' (...[])                                                                                                                                                                                                                                                                                                       
DEBG [1672297752.671966] [src/chainstate/stacks/index/trie.rs:990] [chains-coordinator-0.0.0.0:20443] Next root hash is 0000000000000000000000000000000000000000000000000000000000000000 (update_skiplist=false)

[perplexedpigmy]

Do these browser glitches happen often, or is there maybe a flow in the consensus mechanisms?

We noticed the failure because the balance was wrong, so we verified the burning and indeed that one (22adb4110490fbe380ad3c5891fdb4fefe3a7f44ef35a1f2042da27aa12ee656 ) failed.

[perplexedpigmy]

Here is the transaction queried by the API, status is abort_by_response.

{
    "tx_id": "0x22adb4110490fbe380ad3c5891fdb4fefe3a7f44ef35a1f2042da27aa12ee656",
    "nonce": 17,
    "fee_rate": "200000",
    "sender_address": "SPF8P53TXE81XMBVXXERTT513R0SV8PYTNNC9TKZ",
    "sponsored": false,
    "post_condition_mode": "allow",
    "post_conditions": [
        {
            "type": "fungible",
            "condition_code": "sent_less_than_or_equal_to",
            "amount": "300000000",
            "principal": {
                "type_id": "principal_standard",
                "address": "SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V"
            },
            "asset": {
                "contract_name": "Wrapped-Bitcoin",
                "asset_name": "Wrapped-Bitcoin",
                "contract_address": "SP3DX3H4FEYZJZ586MFBS25ZW3HZDMEW92260R2PR"
            }
        }
    ],
    "anchor_mode": "any",
    "is_unanchored": false,
    "block_hash": "0x5bc2030632a55b33f08e2971678e75290df76d3c8e23129b830d39c37afb6d28",
    "parent_block_hash": "0x625bef14fc9b7ccfe2e9c1adb592e8f6a07d9088c282b7567ddad718b0380753",
    "block_height": 88978,
    "burn_block_time": 1672297725,
    "burn_block_time_iso": "2022-12-29T07:08:45.000Z",
    "parent_burn_block_time": 1672297303,
    "parent_burn_block_time_iso": "2022-12-29T07:01:43.000Z",
    "canonical": true,
    "tx_index": 1,
    "tx_status": "abort_by_response",
    "tx_result": {
        "hex": "0x080100000000000000000000000000000001",
        "repr": "(err u1)"
    },
    "microblock_hash": "0x1377072827d067a8bf5e33598482ab6fd8c248d23424b1641ec6686b300b7eec",
    "microblock_sequence": 0,
    "microblock_canonical": true,
    "event_count": 0,
    "events": [],
    "execution_cost_read_count": 6,
    "execution_cost_read_length": 10625,
    "execution_cost_runtime": 22146,
    "execution_cost_write_count": 2,
    "execution_cost_write_length": 1,
    "tx_type": "contract_call",
    "contract_call": {
        "contract_id": "SP3DX3H4FEYZJZ586MFBS25ZW3HZDMEW92260R2PR.Wrapped-Bitcoin",
        "function_name": "burn-tokens",
        "function_signature": "(define-public (burn-tokens (burn-amount uint) (burn-from principal)))",
        "function_args": [
            {
                "hex": "0x0100000000000000000000000011e1a300",
                "repr": "u300000000",
                "name": "burn-amount",
                "type": "uint"
            },
            {
                "hex": "0x0516fc712c8df9f706e26bc23cde811994194a9a6594",
                "repr": "'SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V",
                "name": "burn-from",
                "type": "principal"
            }
        ]
    }
}

[jcnelson]

One of these days I will learn to read 🤦

The node output indicates that the transaction was processed, but it returned (err u1) as reported on the explorer. We can even see the output from print:

(tuple (action "burn-tokens") (burn-amount u300000000) (burn-from SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V)) 

So, the fact that this transaction failed is no longer in question.

However, looking at the address in question, it doesn't appear that it would have had a balance of 3 xBTC at the time of the call? Take a look: https://explorer.stacks.co/address/SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V?chain=mainnet

[jcnelson]

Specifically, the transaction that gives this address 3 xBTC (https://explorer.stacks.co/txid/0x69178b707ae0c900d5311235d74431771c959a6781236b12ceba573c8e323a43?chain=mainnet) got mined after the failed call to burn-tokens, but in the same block.

[perplexedpigmy]

I missed it as well, to be fair the u1 appears at the very end of a very long line, after the phrase "processed successfully"

[jcnelson]

So, I don't think there's a bug here. The address SP3Y72B4DZ7VGDRKBR8YDX08SJGCMN6K5JKF2F13V did not have 3 xBTC at the time of the call to burn-tokens, which would have caused ft-burn? to correctly error out with (err u1).

[perplexedpigmy]

That will explain it, and it will be my preferred explanation,
I was pretty certain that we should have had the correct balance, but I can easily code something to verify the balance in time, and maybe that's what I should have done first.

For now thanks for your efforts, I will post here my findings

[perplexedpigmy]

Thanks @jcnelson you are absolutely correct,
The transfer and burn found themselves in the same block, and despite the fact that the transferred was broadcasted before the burn, the node, so it seems, has the liberty of re-arranging them as it sees fit.

(edit) still some mystery there, the handling code was supposed to wait until the transfer was successfully confirmed in an anchor block, and only then broadcast the burn. Both transactions ending up in the same block shouldn't be possible. I'll investigate farther.

[jcnelson]

If it helps any, your burn was in an unconfirmed microblock before it was mined in an anchored block. Miners may not see all microblocks, and may not confirm all of them; in such cases, miners can instead include the transactions in their anchored blocks.

[jcnelson]

Closing this issue as completed.