Confirmed transactions showing up in mempool as pending

[yknl]

There seems to have been a regression of confirmed transactions showing up as pending in the mempool. For example at the time of this issue opening:

API call to mempool endpoint for address SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE:
https://stacks-node-api.stacks.co/extended/v1/tx/mempool?address=SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE

returns

{"limit":96,"offset":0,"total":3,"results":[{"tx_id":"0x73b9133f4898627d1db910046077d4bd1ac55240500550b17e4f5714797a5490","tx_status":"pending","tx_type":"contract_call","receipt_time":1623099122,"receipt_time_iso":"2021-06-07T20:52:02.000Z","nonce":28,"fee_rate":"352","sender_address":"SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE","sponsored":false,"post_condition_mode":"deny","post_conditions":[],"contract_call":{"contract_id":"SPXVRSEH2BKSXAEJ00F1BY562P45D5ERPSKR4Q33.xverse-pool-v1","function_name":"delegate-stx"}},{"tx_id":"0x5a26c0d2f4d558d15899c1c2b0bd90bf929c025c94a3fc612dab312e89f641c4","tx_status":"pending","tx_type":"contract_call","receipt_time":1623099108,"receipt_time_iso":"2021-06-07T20:51:48.000Z","nonce":27,"fee_rate":"205","sender_address":"SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE","sponsored":false,"post_condition_mode":"deny","post_conditions":[],"contract_call":{"contract_id":"SP000000000000000000002Q6VF78.pox","function_name":"allow-contract-caller"}},{"tx_id":"0x6f46f2155945ea56f91f87ca31e1ec57f0075ac5bdbffee26412d02e3cf837e9","tx_status":"pending","tx_type":"token_transfer","receipt_time":1623098759,"receipt_time_iso":"2021-06-07T20:45:59.000Z","nonce":27,"fee_rate":"180","sender_address":"SP2M2ZWRQZ3G0W2574H7CG355EGZDM26YN9T6F2ZA","sponsored":false,"post_condition_mode":"deny","token_transfer":{"recipient_address":"SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE","amount":"1000","memo":"0x68656c6c6f0000000000000000000000000000000000000000000000000000000000"}}]}

The last transaction, id 0x6f46f2155945ea56f91f87ca31e1ec57f0075ac5bdbffee26412d02e3cf837e9 shows as pending but it's actually confirmed if you query the tx endpoint.

https://stacks-node-api.stacks.co/extended/v1/tx/0x6f46f2155945ea56f91f87ca31e1ec57f0075ac5bdbffee26412d02e3cf837e9

returns

{"tx_id":"0x6f46f2155945ea56f91f87ca31e1ec57f0075ac5bdbffee26412d02e3cf837e9","tx_type":"token_transfer","nonce":27,"fee_rate":"180","sender_address":"SP2M2ZWRQZ3G0W2574H7CG355EGZDM26YN9T6F2ZA","sponsored":false,"post_condition_mode":"deny","tx_status":"success","block_hash":"0x53ba86e38e7812d778350eec346896e47fdf02a7d306c48d61f1d5b0a91d014a","block_height":17849,"burn_block_time":1623099138,"burn_block_time_iso":"2021-06-07T20:52:18.000Z","canonical":true,"tx_index":4,"tx_result":{"hex":"0x0703","repr":"(ok true)"},"token_transfer":{"recipient_address":"SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE","amount":"1000","memo":"0x68656c6c6f0000000000000000000000000000000000000000000000000000000000"},"events":[{"event_index":0,"event_type":"stx_asset","asset":{"asset_event_type":"transfer","sender":"SP2M2ZWRQZ3G0W2574H7CG355EGZDM26YN9T6F2ZA","recipient":"SP7XSVPCEZFNDWVMQ7F2W5TDQDDHBQZ04NSBFZYE","amount":"1000"}}],"event_count":1}

[agraebe]

@asimm241 could you please review? thanks!

[asimm241]

@asimm241 could you please review? thanks!

I'm looking into it.

[asimm241]

@agraebe I haven't figure out exactly what the problem is.
I think it could be because of restoring MempoolTxs during re-org but to determine that we need to check the database and look for non-canonical transactions. I don't think I can access live db so I can't do further investigation.

[zone117x]

It looks like this may have been fixed in the microblocks PR, I don't see the same issue on the deployment at: https://stacks-node-api-microblocks.stacks.co
I think we should verify that this issue is still happening with the microblocks changes before doing a bunch more debugging.

[agraebe]

@zone117x was this resolved with the mircoblocks PRs merged in?

[zone117x]

It was not, there was a recent report of this same issue hirosystems/explorer#534

I found a couple areas in the code that are likely causing this, but haven't had a time fix and test

[zone117x]

Update on this issue:
It looks like re-org changes from the microblock feature at least decreased the probability of this issue manifesting. From what I can tell, it only happens through a specific series of anchor block and microblock re-orgs, and it also appears to be eventually self-correcting (through dropped_mempool events I suspect).

Using the following query to find these instances:

select encode(mempool_txs.tx_id, 'hex') txid, receipt_time, * from mempool_txs
inner join txs
on txs.tx_id = mempool_txs.tx_id
where mempool_txs.pruned = false
and txs.canonical = true
and txs.microblock_canonical = true

It usually returns zero results from the mainnet API dbs.

I've isolated and normalized a series of stacks-node events that can reproduce the issue locally
events-sample.tsv.zip, but I'm not confident that the fixes I've explored so far won't result on other unwanted behavior. The challenge is that while in the nested re-org handling paths, it's difficult to determine if a tx will ultimately end up as either orphaned or canonical in order to know if a tx should be pruned or restored from the mempool.

I think a safe fix would be something like 1. collect an array of all txids that were "restored" into the mempool during the recursive re-org handling logic, 2. at the end of the block update logic, identified any of these txids that ended up as fully canonical and re-prune them. The problem with this approach is that it will make the event digestion path slower (ultimately slowing down event-replay deployments), but that seems unavoidable right now. I'll open a PR once I have something like that working and the associated unit tests.

[zone117x]

At least one of the code paths that led to this were fixed in #817
Although it's possible there could be another.

For now, going to assume this is fixed and close out the issue. Please comment if anyone sees this again and I'll re-open.