Error in msapproval task: failed to find transaction: pending transaction 1 not found

[frrist]

Describe the bug:

msapproval task error: failed to find transaction: pending transaction 1 not found:

lily/tasks/msapprovals/msapprovals.go

Lines 240 to 257 in 0087552

	var tx *transaction
	if err := prevActorState.ForEachPendingTxn(func(id int64, txn multisig.Transaction) error {
	if id == int64(params.ID) {
	tx = &transaction{
	id: int64(params.ID),
	to: txn.To.String(),
	value: txn.Value.String(),
	}
	}
	return nil
	}); err != nil {
	return false, nil, xerrors.Errorf("failed to read transaction details: %w", err)
	}
	if tx == nil {
	return false, nil, xerrors.Errorf("pending transaction %d not found", params.ID)
	}

Steps to Reproduce:

Lily Version: v0.8.5

[frrist]

sentinel archiver hit the same error:

2022-01-27T12:07:55.060Z INFO archiver sentinel-archiver/verify.go:146 error found for height 1493195: [{"Addr":"f2unf6ajcfrxis6wcehnwws2aocb46k5qn3u7ta3q","Error":"failed to find transaction: pending transaction 1 not found"}] {"task": "msapprovals", "export_file": "/mnt/disk1/archiver/rawcsv/mainnet/arch0127-2022-01-25-visor_processing_reports.csv"}

[frrist]

Propose message to said actor: f2unf6ajcfrxis6wcehnwws2aocb46k5qn3u7ta3q/f01708979

+--------------------------------------------------------------+-------+-----------------------------------------+-----------------------------------------+-----+-------+---------------------------------------------------------------------------------------------------------+
|cid                                                           |height |from                                     |to                                       |value|method |params                                                                                                   |
+--------------------------------------------------------------+-------+-----------------------------------------+-----------------------------------------+-----+-------+---------------------------------------------------------------------------------------------------------+
|bafy2bzacedx3udxym3v5ixdrscdpfqmkuqkyo3kp6xukk45fztrf3stlrdik4|1493194|f1oloydmtt7i7ptkogsfj4op6k7i2fjks7te26h2i|f2unf6ajcfrxis6wcehnwws2aocb46k5qn3u7ta3q|0    |Propose|{"To": "f1oloydmtt7i7ptkogsfj4op6k7i2fjks7te26h2i", "Value": "50000000000000", "Method": 0, "Params": ""}|
+--------------------------------------------------------------+-------+-----------------------------------------+-----------------------------------------+-----+-------+---------------------------------------------------------------------------------------------------------+

And the Approve:

|cid                                                           |height |from                                     |to                                       |value|method |params                                                                  |
+--------------------------------------------------------------+-------+-----------------------------------------+-----------------------------------------+-----+-------+------------------------------------------------------------------------+
|bafy2bzacedne7w4z7e435pirgywcilrlh2i7c3htcd2ohj2mmirk42ydywywm|1493195|f1madhmcxcv67mtausk7gt4tvqlmwsd6aoo2ehzgy|f2unf6ajcfrxis6wcehnwws2aocb46k5qn3u7ta3q|0    |Approve|{"ID": 1, "ProposeHash": "S1VsLnyzzFDLppsad3egcDI6Fnza6WDW6c3fg4SRjSw="}|
+--------------------------------------------------------------+-------+-----------------------------------------+-----------------------------------------+-----+-------+------------------------------------------------------------------------+

All Transactions:

+-------+-----------+--------------------------------------------------------------+--------------+-----------------------------------------+--------------+------+------+-------------+
|height |multisig_id|state_root                                                    |transaction_id|to                                       |value         |method|params|approved     |
+-------+-----------+--------------------------------------------------------------+--------------+-----------------------------------------+--------------+------+------+-------------+
|1493128|f01708979  |bafy2bzacea2f63ut7d4kuf62m2cbaxbx5ksyltclrb6cz4wiyylxigogfxumq|0             |f1oloydmtt7i7ptkogsfj4op6k7i2fjks7te26h2i|50000000000000|0     |NULL  |["f01518248"]|
|1493195|f01708979  |bafy2bzacecaoklpagbxbjrh7lvv5ace4x5qvdxtf77236ex5ojhquz6hjueqa|1             |f1oloydmtt7i7ptkogsfj4op6k7i2fjks7te26h2i|50000000000000|0     |NULL  |["f01518248"]|
+-------+-----------+--------------------------------------------------------------+--------------+-----------------------------------------+--------------+------+------+-------------+

All actor states:

+---------+--------------+--------------------------------------------------------------+-----+---------------+--------------------------------------------------------------+-------+
|id       |code          |head                                                          |nonce|balance        |state_root                                                    |height |
+---------+--------------+--------------------------------------------------------------+-----+---------------+--------------------------------------------------------------+-------+
|f01708979|fil/6/multisig|bafy2bzacecertnsozzhv6sqe77l53nlrk6atpgnlyouvpgbpppxpz6pfzyccy|0    |0              |bafy2bzacebtwcs735kcznqbn6jytdpk4gocllerlsuinqzvqu7kmvadfrxqn2|1493094|
|f01708979|fil/6/multisig|bafy2bzacecertnsozzhv6sqe77l53nlrk6atpgnlyouvpgbpppxpz6pfzyccy|0    |100000000000000|bafy2bzacedmrvhhjdzsl36khnrubmzauump7rimirlvqybyzeibvxldkgsve6|1493109|
|f01708979|fil/6/multisig|bafy2bzacecs635efkhnfdow4dncv2hradqag6pyh3yzbitar534jqugbvgioa|0    |100000000000000|bafy2bzacea2f63ut7d4kuf62m2cbaxbx5ksyltclrb6cz4wiyylxigogfxumq|1493128|
|f01708979|fil/6/multisig|bafy2bzacece2wfw7vwr2kcq2mgisasbdg6keuszijcosdteesvlm53mel2aha|0    |50000000000000 |bafy2bzacecvrv2ijmkut6tkuojkcx3omkrr5my6ijwrl6ibzwuoyjimc4izva|1493163|
|f01708979|fil/6/multisig|bafy2bzacecfbau5s4qnyzp4xhpyf35lrhl2vlplvidkzz43fpt3aovfq36r4m|0    |50000000000000 |bafy2bzacecaoklpagbxbjrh7lvv5ace4x5qvdxtf77236ex5ojhquz6hjueqa|1493195|
|f01708979|fil/6/multisig|bafy2bzaceahd6drfd3f7ze5so45p5putqqwy622622yyjqgsfad5zi4xizycq|0    |0              |bafy2bzacebw6jhhfv6ncevuqipaynence4ses7bzr2wceu6siitkolldrnfrs|1493196|
+---------+--------------+--------------------------------------------------------------+-----+---------------+--------------------------------------------------------------+-------+

+--------------------------------------------------------------+------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+
|head                                                          |code                          |state                                                                                                                                                                                                                                                |height |
+--------------------------------------------------------------+------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+
|bafy2bzacece2wfw7vwr2kcq2mgisasbdg6keuszijcosdteesvlm53mel2aha|bafkqadtgnfwc6nrpnv2wy5djonuwo|{"Signers": ["f01518248", "f01708980", "f01708371"], "NextTxnID": 1, "StartEpoch": 0, "PendingTxns": {"/": "bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay"}, "InitialBalance": "0", "UnlockDuration": 0, "NumApprovalsThreshold": 2}|1493163|
|bafy2bzacecfbau5s4qnyzp4xhpyf35lrhl2vlplvidkzz43fpt3aovfq36r4m|bafkqadtgnfwc6nrpnv2wy5djonuwo|{"Signers": ["f01518248", "f01708980", "f01708371"], "NextTxnID": 2, "StartEpoch": 0, "PendingTxns": {"/": "bafy2bzaceb44qkv2jl53st7qqayyapgkkmrwuwlk32kb6tyn4jdekwqgozxag"}, "InitialBalance": "0", "UnlockDuration": 0, "NumApprovalsThreshold": 2}|1493195|
|bafy2bzaceahd6drfd3f7ze5so45p5putqqwy622622yyjqgsfad5zi4xizycq|bafkqadtgnfwc6nrpnv2wy5djonuwo|{"Signers": ["f01518248", "f01708980", "f01708371"], "NextTxnID": 2, "StartEpoch": 0, "PendingTxns": {"/": "bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay"}, "InitialBalance": "0", "UnlockDuration": 0, "NumApprovalsThreshold": 2}|1493196|
+--------------------------------------------------------------+------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+

[frrist]

Actor State Before all messages:

Height: 1493163
State: {"Signers": ["f01518248", "f01708980", "f01708371"], "NextTxnID": 1, "StartEpoch": 0, "PendingTxns": {"/": "bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay"}, "InitialBalance": "0", "UnlockDuration": 0, "NumApprovalsThreshold": 2}

Propose Message in block at height 1493194 From: f1oloydmtt7i7ptkogsfj4op6k7i2fjks7te26h2i/f01518248
Propose Executed in block at height 1493195

Height: 1493195
State: {"Signers": ["f01518248", "f01708980", "f01708371"], "NextTxnID": 2, "StartEpoch": 0, "PendingTxns": {"/": "bafy2bzaceb44qkv2jl53st7qqayyapgkkmrwuwlk32kb6tyn4jdekwqgozxag"}, "InitialBalance": "0", "UnlockDuration": 0, "NumApprovalsThreshold": 2}

Approve Message in block at height 1493195 From: f1madhmcxcv67mtausk7gt4tvqlmwsd6aoo2ehzgy/f01708980
Approve Executed in block at height 1493196

Height: 1493196
{"Signers": ["f01518248", "f01708980", "f01708371"], "NextTxnID": 2, "StartEpoch": 0, "PendingTxns": {"/": "bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay"}, "InitialBalance": "0", "UnlockDuration": 0, "NumApprovalsThreshold": 2}

"PendingTxns": {"/": "bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay"} Means empty list
Height 1493163 to 1493195: 0 pending transactions: bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay
Height 1493195: 1 pending transactions: bafy2bzaceb44qkv2jl53st7qqayyapgkkmrwuwlk32kb6tyn4jdekwqgozxag
Height 1493196: 0 pending transactions: bafy2bzaceamp42wmmgr2g2ymg46euououzfyck7szknvfacqscohrvaikwfay

From the error message: error found for height 1493195: means pts was height 1493195:

lily/tasks/msapprovals/msapprovals.go

Lines 43 to 46 in 0087552

	report := &visormodel.ProcessingReport{
	Height: int64(pts.Height()),
	StateRoot: pts.ParentState().String(),
	}

which is passed to getTransactionIfApplied:

lily/tasks/msapprovals/msapprovals.go

Lines 74 to 81 in 0087552

	applied, tx, err := p.getTransactionIfApplied(ctx, m.Message, m.Receipt, pts)
	if err != nil {
	errorsDetected = append(errorsDetected, &MultisigError{
	Addr: m.Message.To.String(),
	Error: xerrors.Errorf("failed to find transaction: %w", err).Error(),
	})
	continue
	}

has a parent state was 1493194 which represents an actor state with zero pending transactions:

lily/tasks/msapprovals/msapprovals.go

Lines 230 to 257 in 0087552

	act, err := p.node.StateGetActor(ctx, msg.To, pts.Parents())
	if err != nil {
	return false, nil, xerrors.Errorf("failed to load previous actor: %w", err)
	}
	prevActorState, err := multisig.Load(p.node.Store(), act)
	if err != nil {
	return false, nil, xerrors.Errorf("failed to load previous actor state: %w", err)
	}
	var tx *transaction
	if err := prevActorState.ForEachPendingTxn(func(id int64, txn multisig.Transaction) error {
	if id == int64(params.ID) {
	tx = &transaction{
	id: int64(params.ID),
	to: txn.To.String(),
	value: txn.Value.String(),
	}
	}
	return nil
	}); err != nil {
	return false, nil, xerrors.Errorf("failed to read transaction details: %w", err)
	}
	if tx == nil {
	return false, nil, xerrors.Errorf("pending transaction %d not found", params.ID)
	}

I think this means we are passing the wrong tipset to getTransactionIfApplied. We should instead be passing ts.

[iand]

Any thoughts on why we are seeing this happen now with this single multisig transaction? Answered below.

[iand]

I think you are correct. This could be an edge case where the proposal and approval occur on sequential tipsets.

According to the comment in getTransactionIfApplied, pts is the tipset containing the approve message. At this point the stateroot refers to the state after the previous tipset's messages were applied. So the state contains the proposal. However the code looks at the parent of pts which, in this edge case, is the state just before the proposal. Most of the time there is more than one tipset between proposal and approval, in which case this logic would work, even though it has this bug.

lily/tasks/msapprovals/msapprovals.go

Lines 227 to 229 in 0087552

	// Get state of actor before the message was applied
	// pts is the tipset containing the messages, so we need the state as seen at the start of message processing
	// for that tipset