tari icon indicating copy to clipboard operation
tari copied to clipboard
verified publisher icon tari-project

Wallet Recovery creates new pending transactions from completed transactions

Open brianp opened this issue 3 years ago • 0 comments

Description

When running a recovery on a wallet containing 4 transactions, 2 interactive, and 2 one-sided, the 2 interactive completed transactions are duplicated with new commitments and listed under pending transactions... sometimes. This problem is intermittent.

It seems during recovery sometimes the recovering wallet does not have all the information required to recognize that the interactive transactions are completed.

  • NextNet 0.49.0-rc.2

Relevant Sender Log lines:

base_layer.2.log:
  43985: 2023-04-24 17:36:22.587410000 [wallet::transaction_service::protocols::send_protocol] [Thread:13152813056] INFO  Starting Transaction Send protocol for TxId: 9490431504440150381 at Stage Initial
  43991: 2023-04-24 17:36:22.661983000 [wallet::output_manager_service] [Thread:13152813056] DEBUG Prepared transaction (TxId: 9490431504440150381) to send
  43992: 2023-04-24 17:36:22.662376000 [wallet::transaction_service::protocols::send_protocol] [Thread:13152813056] INFO  Attempting to Send Transaction (TxId: 9490431504440150381) to recipient with address: 🌠🌂🎁🎠🚁💊🍦🐢🐰👗🍩👟👣🍣🔔🐀🐝👿🚂🌴👓🔫💀🎼💻🐢🐉🚒💔🐘🍋🐝📣
  43993: 2023-04-24 17:36:22.663712000 [wallet::transaction_service::protocols::send_protocol] [Thread:13154922496] INFO  Transaction (TxId: 9490431504440150381) Send to Neighbours for Store and Forward successful with Message Tags: MessageTag(6255524176815566961)
  43995: 2023-04-24 17:36:25.839497000 [wallet::transaction_service::protocols::send_protocol] [Thread:13152813056] DEBUG Discovery of 🌠🌂🎁🎠🚁💊🍦🐢🐰👗🍩👟👣🍣🔔🐀🐝👿🚂🌴👓🔫💀🎼💻🐢🐉🚒💔🐘🍋🐝📣 completed for TxID: 9490431504440150381
  43996: 2023-04-24 17:36:25.839516000 [wallet::transaction_service::tasks] [Thread:13152813056] DEBUG Transaction (TxId: 9490431504440150381) Direct Send to 0a013e46edaf2c7d869b2da1a52bd46b7baaee0c97dbab5dc47d6cf1b5761c7b queued with Message Tag#3923688517368628720
  43997: 2023-04-24 17:36:25.839651000 [wallet::transaction_service::tasks] [Thread:13154922496] INFO  Direct Send process for Transaction TX_ID: 9490431504440150381 was successful with Message: Tag#3923688517368628720
  43998: 2023-04-24 17:36:25.840816000 [wallet::transaction_service::protocols::send_protocol] [Thread:13154922496] INFO  Pending Outbound Transaction TxId: TxId(9490431504440150381) added. Waiting for Reply or Cancellation
  43999: 2023-04-24 17:36:25.842445000 [wallet::transaction_service::protocols::send_protocol] [Thread:13154922496] INFO  Transaction Recipient Reply for TX_ID = 9490431504440150381 received
  44000: 2023-04-24 17:36:25.842606000 [wallet::transaction_service::tasks] [Thread:13163360256] DEBUG Finalized Transaction (TxId: 9490431504440150381) Direct Send to 0a013e46edaf2c7d869b2da1a52bd46b7baaee0c97dbab5dc47d6cf1b5761c7b queued with Message Tag#9198796384934667881
  44001: 2023-04-24 17:36:25.842651000 [wallet::transaction_service::tasks] [Thread:13163360256] INFO  Direct Send process for Finalized Transaction TX_ID: 9490431504440150381 was successful with Message: Tag#9198796384934667881
  44002: 2023-04-24 17:36:25.842667000 [wallet::transaction_service::tasks::send_finalized_transaction] [Thread:13163360256] INFO  Direct Send finalize result was true. Sending SAF for TxId: 9490431504440150381 to recipient with Public Key: 0a013e46edaf2c7d869b2da1a52bd46b7baaee0c97dbab5dc47d6cf1b5761c7b
  44003: 2023-04-24 17:36:25.843007000 [wallet::notifier] [Thread:13152813056] DEBUG Transaction sent tx_id: 9490431504440150381
  44004: 2023-04-24 17:36:25.843305000 [wallet::transaction_service::tasks::send_finalized_transaction] [Thread:13152813056] INFO  Sending Finalized Transaction (TxId: 9490431504440150381) to Neighbours for Store and Forward successful with Message Tags: [MessageTag(7834860785411336858)]
  44005: 2023-04-24 17:36:25.844321000 [wallet::transaction_service::protocols::broadcast_protocol] [Thread:13157031936] INFO  Transaction Broadcast protocol (TxId: 9490431504440150381) Base Node Public key updated to 068119f1983b16c2dd74817365070421824964b252e6042b59145cdcd8e8a62b (NodeID: c2d07250ff3c2a74baa3e93cb8)
  44006: 2023-04-24 17:36:25.844377000 [wallet::transaction_service::protocols::broadcast_protocol] [Thread:13157031936] INFO  Submitting Transaction (TxId: 9490431504440150381) with signature 'befce56edffbd6d2a58fc4264c9cf4ca7becaaec3b3077999ff3c51d13e76d06' to Base Node
  44007: 2023-04-24 17:36:26.443435000 [wallet::transaction_service::protocols::broadcast_protocol] [Thread:13152813056] INFO  Transaction (TxId: 9490431504440150381) successfully submitted to UnconfirmedPool
  44078: 2023-04-24 17:37:33.542265000 [wallet::transaction_service::protocols::validation_protocol] [Thread:13154922496] WARN  Marking transaction 9490431504440150381 as unmined and confirmed 'false' with block 'false' (Operation ID: 16495893450661566606)
  44099: 2023-04-24 17:37:33.543139000 [wallet::transaction_service::protocols::validation_protocol] [Thread:13154922496] DEBUG Updated transaction 9490431504440150381 as unmined (Operation ID: 16495893450661566606)
  44242: 2023-04-24 17:38:54.865348000 [wallet::transaction_service::protocols::validation_protocol] [Thread:13163360256] DEBUG Updating transaction 9490431504440150381 as mined and confirmed 'false' (Operation ID: 18362197204189506857)
  44270: 2023-04-24 17:38:54.871246000 [wallet::notifier] [Thread:13163360256] DEBUG transaction_mined_unconfirmed tx_id: 9490431504440150381
  44378: 2023-04-24 17:39:25.126847000 [wallet::transaction_service::protocols::validation_protocol] [Thread:13152813056] DEBUG Updating transaction 9490431504440150381 as mined and confirmed 'false' (Operation ID: 2623062346981384377)
  44388: 2023-04-24 17:39:25.128972000 [wallet::notifier] [Thread:13157031936] DEBUG transaction_mined_unconfirmed tx_id: 9490431504440150381
  44425: 2023-04-24 17:39:26.447631000 [wallet::transaction_service::protocols::broadcast_protocol] [Thread:13165469696] INFO  Querying Transaction (TxId: 9490431504440150381) status on Base Node
  44432: 2023-04-24 17:39:27.076581000 [wallet::transaction_service::service] [Thread:13165469696] DEBUG Transaction Broadcast Protocol for TxId: 9490431504440150381 completed successfully
  44605: 2023-04-24 17:41:22.142360000 [wallet::transaction_service::protocols::validation_protocol] [Thread:13163360256] DEBUG Updating transaction 9490431504440150381 as mined and confirmed 'false' (Operation ID: 15759314774215001683)
  44611: 2023-04-24 17:41:22.145208000 [wallet::notifier] [Thread:13152813056] DEBUG transaction_mined_unconfirmed tx_id: 9490431504440150381
  44735: 2023-04-24 17:42:09.822977000 [wallet::transaction_service::protocols::validation_protocol] [Thread:13167579136] DEBUG Updating transaction 9490431504440150381 as mined and confirmed 'true' (Operation ID: 9453213935288673951)
  44760: 2023-04-24 17:42:09.837415000 [wallet::notifier] [Thread:13165469696] DEBUG transaction_mined tx_id: 9490431504440150381
  45597: 2023-04-24 17:53:14.583569000 [wallet::transaction_service::service] [Thread:13167579136] DEBUG A repeated Transaction Reply (TxId: 9490431504440150381) has been received. Reply is being resent.
  45598: 2023-04-24 17:53:14.583710000 [wallet::transaction_service::tasks] [Thread:13152813056] DEBUG Finalized Transaction (TxId: 9490431504440150381) Direct Send to 0a013e46edaf2c7d869b2da1a52bd46b7baaee0c97dbab5dc47d6cf1b5761c7b queued with Message Tag#16533394480954537131
  45600: 2023-04-24 17:53:14.583771000 [wallet::transaction_service::tasks] [Thread:13152813056] INFO  Direct Send process for Finalized Transaction TX_ID: 9490431504440150381 was successful with Message: Tag#16533394480954537131
  45602: 2023-04-24 17:53:14.583947000 [wallet::transaction_service::tasks::send_finalized_transaction] [Thread:13152813056] INFO  Direct Send finalize result was true. Sending SAF for TxId: 9490431504440150381 to recipient with Public Key: 0a013e46edaf2c7d869b2da1a52bd46b7baaee0c97dbab5dc47d6cf1b5761c7b
  45604: 2023-04-24 17:53:14.584508000 [wallet::transaction_service::tasks::send_finalized_transaction] [Thread:13154922496] INFO  Sending Finalized Transaction (TxId: 9490431504440150381) to Neighbours for Store and Forward successful with Message Tags: [MessageTag(17048575434643132064)]

Relevant Receiver Log Lines

base_layer.log:
   23: 2023-04-24 17:53:10.916249000 [wallet::transaction_service::protocols::receive_protocol] [Thread:13073494016] INFO  Starting Transaction Receive protocol for TxId: 9490431504440150381 at Stage Initial
   25: 2023-04-24 17:53:11.013759000 [wallet::transaction_service::tasks] [Thread:13067165696] DEBUG Transaction Reply (TxId: 9490431504440150381) Direct Send to e01a1c449375fb6dbef5727b973b6295a18d55a87b1d7e466d555d7ba89e1e39 queued with Message Tag#6907657483941456535
   27: 2023-04-24 17:53:14.416346000 [wallet::transaction_service::tasks] [Thread:13067165696] INFO  Direct Send process for Transaction Reply TX_ID: 9490431504440150381 was successful with Message: Tag#6907657483941456535
   30: 2023-04-24 17:53:14.416640000 [wallet::transaction_service::tasks::send_transaction_reply] [Thread:13067165696] INFO  Direct Send reply result was true. Sending SAF for TxId: 9490431504440150381 to recipient with address: 🗽🍉🍋🎒👀🐗🚫🐊💭🚜🐑🐝👓🍺🏁👑👟🐸🎲👽🐝🍌🐣🎠🐊🎲🎼🐝👽👚🍍🍸🎒
   32: 2023-04-24 17:53:14.417826000 [wallet::transaction_service::tasks::send_transaction_reply] [Thread:13077712896] INFO  Sending Transaction Reply (TxId: 9490431504440150381) to Neighbours for Store and Forward successful with Message Tags: [MessageTag(14721589626627623989), MessageTag(10072821806365113730), MessageTag(17479248544685881583), MessageTag(15789761531597823115), MessageTag(6365347126435992428), MessageTag(10090827069243577707)]
   36: 2023-04-24 17:53:14.419595000 [wallet::transaction_service::protocols::receive_protocol] [Thread:13077712896] INFO  Transaction with TX_ID = 9490431504440150381 received from 🗽🍉🍋🎒👀🐗🚫🐊💭🚜🐑🐝👓🍺🏁👑👟🐸🎲👽🐝🍌🐣🎠🐊🎲🎼🐝👽👚🍍🍸🎒. Reply Sent
   37: 2023-04-24 17:53:14.419789000 [wallet::transaction_service::protocols::receive_protocol] [Thread:13077712896] INFO  Finalized Transaction with TX_ID = 9490431504440150381 received from 🗽🍉🍋🎒👀🐗🚫🐊💭🚜🐑🐝👓🍺🏁👑👟🐸🎲👽🐝🍌🐣🎠🐊🎲🎼🐝👽👚🍍🍸🎒
   46: 2023-04-24 17:53:14.571501000 [wallet::transaction_service::service] [Thread:13079822336] DEBUG Restarting listening for Transaction Finalize for Pending Inbound Transaction TxId: 9490431504440150381
   47: 2023-04-24 17:53:14.571517000 [wallet::transaction_service::protocols::receive_protocol] [Thread:13079822336] INFO  Starting Transaction Receive protocol for TxId: 9490431504440150381 at Stage WaitForFinalize
  260: 2023-04-24 17:54:39.870522000 [wallet::transaction_service::protocols::receive_protocol] [Thread:13069275136] INFO  Transaction Receive Protocol (id: 9490431504440150381) shutting down because it received the shutdown signal
  262: 2023-04-24 17:54:39.870759000 [wallet::transaction_service::protocols::receive_protocol] [Thread:13067165696] INFO  Transaction Receive Protocol (id: 9490431504440150381) shutting down because it received the shutdown signal

brianp avatar Apr 26 '23 08:04 brianp