search

comit-network / xmr-btc-swap

Bitcoin–Monero Cross-chain Atomic Swap
GNU General Public License v3.0
645 stars 79 forks source link

[critical] ASB execution gets stuck #250

Closed da-kami closed 3 years ago

da-kami commented 3 years ago

I ran into a scenario where I triggered a swap successfully, but the ASB remains in BtcLocked forever without locking the XMR. No error / warning or anything useful in the logs, the application just hangs at:

2021-03-01T07:26:56.255656Z  INFO swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::protocol::alice::swap: Current state: btc is locked

I don't understand how this can happen. I though about the execution of the swap getting starved, but I don't understand why it would happen at this point.

Communication with the monero-wallet-rpc through curl is possible without problems - it is running and responding as expected.

Here is the complete ASB log of this run:

     Running `target/release/asb --config /var/external/asb/run/asb-config/config.toml start`
2021-03-01T06:09:42.301209Z  INFO swap::trace: Initialized tracing with level: debug
2021-03-01T06:09:42.302165Z  INFO swap::asb::config: Using config file at default path: /var/external/asb/run/asb-config/config.toml
2021-03-01T06:09:42.351677Z  INFO swap::seed: Read in seed from file: /var/external/asb/run/asb-data/seed.pem
2021-03-01T06:24:49.802205Z DEBUG swap::protocol::alice::event_loop: Connection Established with 12D3KooWKoWwKEgurc4B1pZ1VTZSDsUi76mYYzceAhhHE3vpMWAB
2021-03-01T06:24:49.812572Z DEBUG swap::protocol::alice::quote_response: Received quote request from 12D3KooWKoWwKEgurc4B1pZ1VTZSDsUi76mYYzceAhhHE3vpMWAB
2021-03-01T06:24:49.812753Z ERROR swap::protocol::alice::event_loop: Failed to handle quote request: The amount 7.567182976884 XMR exceeds the configured maximum sell amount of 0.500000000000 XMR XMR
2021-03-01T06:24:49.812922Z ERROR swap::protocol::alice::event_loop: Communication error: Quote Request/Response failure: Inbound failure: ResponseOmission
2021-03-01T06:30:59.463327Z DEBUG swap::protocol::alice::event_loop: Connection Established with 12D3KooWKoWwKEgurc4B1pZ1VTZSDsUi76mYYzceAhhHE3vpMWAB
2021-03-01T06:30:59.467872Z DEBUG swap::protocol::alice::quote_response: Received quote request from 12D3KooWKoWwKEgurc4B1pZ1VTZSDsUi76mYYzceAhhHE3vpMWAB
2021-03-01T06:30:59.468086Z ERROR swap::protocol::alice::event_loop: Failed to handle quote request: The amount 7.562281951640 XMR exceeds the configured maximum sell amount of 0.500000000000 XMR XMR
2021-03-01T06:30:59.468476Z ERROR swap::protocol::alice::event_loop: Communication error: Quote Request/Response failure: Inbound failure: ResponseOmission
2021-03-01T07:21:39.446672Z DEBUG swap::protocol::alice::event_loop: Connection Established with 12D3KooWKoWwKEgurc4B1pZ1VTZSDsUi76mYYzceAhhHE3vpMWAB
2021-03-01T07:21:39.469134Z DEBUG swap::protocol::alice::quote_response: Received quote request from 12D3KooWKoWwKEgurc4B1pZ1VTZSDsUi76mYYzceAhhHE3vpMWAB
2021-03-01T07:21:39.469332Z ERROR swap::protocol::alice::event_loop: Failed to handle quote request: The amount 7.598370932754 XMR exceeds the configured maximum sell amount of 0.500000000000 XMR XMR
2021-03-01T07:21:39.469709Z ERROR swap::protocol::alice::event_loop: Communication error: Quote Request/Response failure: Inbound failure: ResponseOmission
2021-03-01T07:24:15.205515Z DEBUG swap::protocol::alice::event_loop: Connection Established with 12D3KooWRvzPVmsH6Y7hLaMFjQU39LZqtWAhd8zNQDsz3TqNfev9
2021-03-01T07:24:15.211857Z DEBUG swap::protocol::alice::quote_response: Received quote request from 12D3KooWRvzPVmsH6Y7hLaMFjQU39LZqtWAhd8zNQDsz3TqNfev9
2021-03-01T07:24:15.220157Z  INFO swap::protocol::alice::behaviour: Sent quote response
2021-03-01T07:24:16.242767Z  INFO swap::protocol::alice::event_loop: Starting execution setup to sell 0.215830618892 XMR for 0.00099390 BTC (rate of 0.00460500 BTC) with 12D3KooWRvzPVmsH6Y7hLaMFjQU39LZqtWAhd8zNQDsz3TqNfev9
2021-03-01T07:24:19.212651Z  INFO swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::protocol::alice::swap: Current state: started
2021-03-01T07:24:19.212842Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: watching for tx: 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:24:20.183706Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: Received protocol error "missing transaction" from Electrum, retrying...
2021-03-01T07:24:21.989417Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: Received protocol error "missing transaction" from Electrum, retrying...
2021-03-01T07:24:23.792197Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: Received protocol error "missing transaction" from Electrum, retrying...
2021-03-01T07:24:25.597370Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: Received protocol error "missing transaction" from Electrum, retrying...
2021-03-01T07:24:27.424879Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: waiting for tx finality: 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:26:56.046366Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: tx_block_height: BlockHeight(1938362)
2021-03-01T07:26:56.253292Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: latest_block_height: BlockHeight(1938362)
2021-03-01T07:26:56.253467Z DEBUG swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::bitcoin::wallet: confirmations: BlockHeight(1)
2021-03-01T07:26:56.255656Z  INFO swap{id=595fb7e0-b6c9-49f5-9f31-eb7f2a9b781c}: swap::protocol::alice::swap: Current state: btc is locked

CLI logs:

     Running `target/debug/swap_cli buy-xmr --connect-addr /ip4/192.168.1.7/tcp/9876`
2021-03-01T07:22:12.468697Z  INFO swap::trace: Initialized tracing with level: debug
2021-03-01T07:22:12.469843Z  INFO swap_cli: Database and Seed will be stored in directory: /Users/dakami/Library/Application Support/xmr-btc-swap
2021-03-01T07:22:12.638128Z  INFO swap::seed: No seed file found, creating at: /Users/dakami/Library/Application Support/xmr-btc-swap/seed.pem
2021-03-01T07:22:39.705785Z  INFO swap_cli: Connection to Bitcoin wallet succeeded, balance: 0.00000000 BTC
2021-03-01T07:22:45.456892Z  INFO swap_cli: Created Monero wallet for blockchain monitoring with name swap-tool-blockchain-monitoring-wallet
2021-03-01T07:22:45.457751Z  INFO swap_cli: The Monero wallet RPC is set up correctly!
2021-03-01T07:22:45.458688Z DEBUG swap_cli: Waiting for BTC at address tb1qf0lnsnahj3rqz6lks4g934nspvnq9sgjm9fyet
2021-03-01T07:24:15.150238Z DEBUG swap_cli: Received 0.00100000 BTC
2021-03-01T07:24:15.156447Z  INFO swap_cli: Swapping 0.00099390 BTC ...
2021-03-01T07:24:15.160139Z  INFO swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::swap: Current state: quote has been requested
2021-03-01T07:24:15.160396Z DEBUG swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::event_loop: Attempt to dial Alice
2021-03-01T07:24:15.161053Z  INFO swap::protocol::bob::event_loop: dialing alice: 12D3KooWCdMKjesXMJz1SiZ7HgotrxuqhQJbP5sgBm2BwP1cqThi
2021-03-01T07:24:15.206273Z  INFO swap::protocol::bob: Requesting quote from: 12D3KooWCdMKjesXMJz1SiZ7HgotrxuqhQJbP5sgBm2BwP1cqThi
2021-03-01T07:24:15.226020Z DEBUG swap::protocol::bob::quote_request: Received quote response from 12D3KooWCdMKjesXMJz1SiZ7HgotrxuqhQJbP5sgBm2BwP1cqThi
2021-03-01T07:24:16.489665Z  INFO swap::protocol::bob: Start execution setup with 12D3KooWCdMKjesXMJz1SiZ7HgotrxuqhQJbP5sgBm2BwP1cqThi
2021-03-01T07:24:19.215487Z  INFO swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::swap: Current state: execution setup done
2021-03-01T07:24:19.215563Z DEBUG swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::event_loop: Attempt to dial Alice
2021-03-01T07:24:19.215737Z DEBUG swap::protocol::bob::event_loop: Already connected to Alice: 12D3KooWCdMKjesXMJz1SiZ7HgotrxuqhQJbP5sgBm2BwP1cqThi
2021-03-01T07:24:19.216120Z DEBUG swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::bitcoin::wallet: signing tx lock: 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:24:19.218296Z DEBUG swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::bitcoin::wallet: signed tx lock: 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:24:19.218456Z  INFO swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::state: 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:24:19.218557Z DEBUG swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::bitcoin::wallet: attempting to broadcast tx: 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:24:19.469575Z  INFO swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::bitcoin::wallet: Bitcoin tx broadcasted! TXID = 5ba33e17414945b69a24fc4c8312496df0af374009a95f27d7aa32a31a042f0d
2021-03-01T07:24:19.483088Z  INFO swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::swap: Current state: btc is locked
2021-03-01T07:26:55.846979Z DEBUG swap{id=bd49bfca-64df-4586-a405-06fd024bf974}: swap::protocol::bob::event_loop: Attempt to dial Alice
2021-03-01T07:26:55.848578Z DEBUG swap::protocol::bob::event_loop: Already connected to Alice: 12D3KooWCdMKjesXMJz1SiZ7HgotrxuqhQJbP5sgBm2BwP1cqThi
da-kami commented 3 years ago

I think I found the problem, it seems that the public monero stagenet node (stagenet.community.xmr.to) that we were using so far is not in sync:

monero-wallet-rpc get_height reports: 783222

but the current block is at 783286 according to https://monero-stagenet.exan.tech/

I hope it is not permanently down given that xmr.to stopped their services. Might be better to sync our own stagenet node after all.

da-kami commented 3 years ago

This is due to the connection to the public monerod daemon failing. Solution is to sync our own stagenet node.