Bob's maker doesn't pick up AccLock sometimes

Open Lederstrumpf opened this issue 4 years ago • 1 comments

Bob's maker log for swap 0x892e932cca6b639484fc3e9cc20609ff5344773da0398994c021024a47a2ddb0:

Dec 14 10:17:20 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:20Z INFO  farcaster_node::swapd::runtime] Starting swap: 0x892e932cca6b639484fc3e9cc20609ff5344773da0398994c021024a47a2ddb0
Dec 14 10:17:20 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:20Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Initial state: BobState(Start)
Dec 14 10:17:21 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:21Z INFO  farcaster_node::service] New service swap<0x892e…ddb0> started
Dec 14 10:17:21 farcaster02 farcasterd[1218595]: [2021-12-14T10:17:21Z INFO  farcaster_node::farcasterd::runtime] Service swap<0x892e…ddb0> is now connected
Dec 14 10:17:21 farcaster02 farcasterd[1218595]: [2021-12-14T10:17:21Z INFO  farcaster_node::farcasterd::runtime] Swap 0x892e…ddb0 is registered; total 35 swaps are known
Dec 14 10:17:21 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:21Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Accepting swap 0x892e…ddb0 as Maker from Taker remote peer peerd<026b9739e4610c2a7e8d585b5a9b81e243a7baabfacae421e47e7b038665ffebb1@0.0.0.0:9766>
Dec 14 10:17:21 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:21Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | State transition: BobState(Start) -> BobState(Commit)
Dec 14 10:17:22 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:22Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Send 0.00001900 BTC to tb1qwzsx8tfthvk8cm26gvx4pa2fj0uqsrtkkxllr3
Dec 14 10:17:22 farcaster02 farcasterd[1223340]: [2021-12-14T10:17:22Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Funding transaction with scriptPubkey: OP_0 OP_PUSHBYTES_20 70a063ad2bbb2c7c6d5a430d50f54993f8080d76
Dec 14 10:17:22 farcaster02 farcasterd[1218595]: [2021-12-14T10:17:22Z INFO  farcaster_node::farcasterd::runtime] 0x892e…ddb0 | Attempting to auto-fund Bitcoin
Dec 14 10:17:22 farcaster02 farcasterd[1218595]: [2021-12-14T10:17:22Z INFO  farcaster_node::farcasterd::runtime] 0x892e…ddb0 | Auto-funded Bitcoin with txid: efb59e38b6381eee377cf4b2f5dbe27d9cc451714803850c28173828461ea06a
Dec 14 10:18:59 farcaster02 farcasterd[1223340]: [2021-12-14T10:18:59Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Funding transaction (efb59e38b6381eee377cf4b2f5dbe27d9cc451714803850c28173828461ea06a) in mempool or blockchain, forward to walletd
Dec 14 10:18:59 farcaster02 farcasterd[1218595]: [2021-12-14T10:18:59Z INFO  farcaster_node::farcasterd::runtime] 0x892e…ddb0 | Your Bitcoin funding completed
Dec 14 10:19:00 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | State transition: BobState(Commit) -> BobState(Reveal)
Dec 14 10:19:00 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Lock transaction (8e841c30db3a4c4bad98210ed3aa2ae7f48024c855654646a6a8c678ba7bb05f)
Dec 14 10:19:00 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Cancel transaction (71312c99f524fbba1853fc4ea4b8b6ea8e5892a8b4393595a39ba44dcdd18df9)
Dec 14 10:19:00 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Refund transaction (8297dca717e2e69a82e35bd35fb79d7f517c803e79df439495efe6d21b075aad)
Dec 14 10:19:00 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | State transition: BobState(Reveal) -> BobState(CoreArb)
Dec 14 10:19:01 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Lock transaction received from walletd
Dec 14 10:19:01 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Broadcasting Lock tx (8e841c30db3a4c4bad98210ed3aa2ae7f48024c855654646a6a8c678ba7bb05f)
Dec 14 10:19:01 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching AccLock on address 58MrBmqaA1xgBiYZyEtYRtP6L5KgxwF8AWxGcZhgPqxuStqkHM2wde11bRNDJwD4KLgTXNy3HgQDXRLKv7KrVND2AHkkCqV
Dec 14 10:19:01 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Buy transaction (9bf8665897aad596aa962e417ca780f47367cd0ff3375451cc1f7b5f3555eda7)
Dec 14 10:19:01 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Cancel transaction received from walletd
Dec 14 10:19:01 farcaster02 farcasterd[1223340]: [2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Refund transaction received from walletd
Dec 14 10:23:25 farcaster02 farcasterd[1223340]: [2021-12-14T10:23:25Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Cancel not on the mempool
Dec 14 10:23:25 farcaster02 farcasterd[1223340]: [2021-12-14T10:23:25Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Buy not on the mempool
Dec 14 10:23:25 farcaster02 farcasterd[1223340]: [2021-12-14T10:23:25Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Refund not on the mempool
Dec 14 10:23:25 farcaster02 farcasterd[1223340]: [2021-12-14T10:23:25Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Lock on mempool but hasn't been mined
Dec 14 10:24:47 farcaster02 farcasterd[1223340]: [2021-12-14T10:24:47Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Lock final with 1 confirmations

Alice's taker log (I funded manually @ 2021-12-14T10:28:12 after auto-funding failed due to insufficient unlocked balance):

[2021-12-14T10:17:18Z INFO  farcaster_node::swapd::runtime] Starting swap: 0x892e932cca6b639484fc3e9cc20609ff5344773da0398994c021024a47a2ddb0
[2021-12-14T10:17:18Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Initial state: AliceState(Start)
[2021-12-14T10:17:18Z INFO  farcaster_node::service] New service peerd<026b9739e4610c2a7e8d585b5a9b81e243a7baabfacae421e47e7b038665ffebb1@159.100.242.14:9766> started
[2021-12-14T10:17:18Z INFO  farcaster_node::peerd::runtime] Initializing connection with the remote peer
[2021-12-14T10:17:18Z INFO  farcaster_node::farcasterd::runtime] Service peerd<026b9739e4610c2a7e8d585b5a9b81e243a7baabfacae421e47e7b038665ffebb1@159.100.242.14:9766> is now connected
[2021-12-14T10:17:18Z INFO  farcaster_node::farcasterd::runtime] Connection 026b9739e4610c2a7e8d585b5a9b81e243a7baabfacae421e47e7b038665ffebb1@159.100.242.14:9766 is registered; total 1 connections are known
[2021-12-14T10:17:18Z ERROR microservices::esb::controller] ESB request processing error: transport-level protocol error: service is offline or not responding
[2021-12-14T10:17:19Z INFO  farcaster_node::service] New service swap<0x892e…ddb0> started
[2021-12-14T10:17:19Z INFO  farcaster_node::farcasterd::runtime] Service swap<0x892e…ddb0> is now connected
[2021-12-14T10:17:19Z INFO  farcaster_node::farcasterd::runtime] Swap 0x892e…ddb0 is registered; total 1 swaps are known
[2021-12-14T10:17:19Z ERROR microservices::esb::controller] ESB request processing error: transport-level protocol error: service is offline or not responding
[2021-12-14T10:17:19Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Proposing to take swap 0x892e…ddb0 to Maker remote peer
[2021-12-14T10:17:19Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | State transition: AliceState(Start) -> AliceState(Commit)
[2021-12-14T10:17:19Z INFO  farcaster_node::syncerd::runtime] Creating new Bitcoin (Testnet) syncer
[2021-12-14T10:17:19Z INFO  farcaster_node::syncerd::runtime] Creating new Monero (Testnet) syncer
[2021-12-14T10:17:19Z INFO  farcaster_node::syncerd::syncer_state] Bitcoin incremented height 2131052
[2021-12-14T10:17:20Z INFO  farcaster_node::service] New service Bitcoin (Testnet) syncer started
[2021-12-14T10:17:20Z INFO  farcaster_node::farcasterd::runtime] Service Bitcoin (Testnet) syncer is now connected
[2021-12-14T10:17:20Z INFO  farcaster_node::service] New service Monero (Testnet) syncer started
[2021-12-14T10:17:20Z INFO  farcaster_node::farcasterd::runtime] Service Monero (Testnet) syncer is now connected
[2021-12-14T10:17:20Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985668
[2021-12-14T10:17:21Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | State transition: AliceState(Commit) -> AliceState(Reveal)
[2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Lock transaction (8e841c30db3a4c4bad98210ed3aa2ae7f48024c855654646a6a8c678ba7bb05f)
[2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Cancel transaction (71312c99f524fbba1853fc4ea4b8b6ea8e5892a8b4393595a39ba44dcdd18df9)
[2021-12-14T10:19:00Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching Refund transaction (8297dca717e2e69a82e35bd35fb79d7f517c803e79df439495efe6d21b075aad)
[2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Cancel transaction received from walletd
[2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Punish transaction received from walletd
[2021-12-14T10:19:01Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | State transition: AliceState(Reveal) -> AliceState(RefundSigs(xmr_locked(false), buy_pub(false), cancel_seen(false), refund_seen(false)))
[2021-12-14T10:19:10Z WARN  electrum_client::client] call 'transaction_get_raw' failed with EOF while parsing a value at line 1 column 0, retry: 1/1
[2021-12-14T10:19:12Z INFO  electrum_client::client] Succesfully created new client
[2021-12-14T10:19:12Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Lock not on the mempool
[2021-12-14T10:19:12Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Cancel not on the mempool
[2021-12-14T10:19:12Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Refund not on the mempool
[2021-12-14T10:20:33Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985669
[2021-12-14T10:22:24Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985670
[2021-12-14T10:23:21Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Lock on mempool but hasn't been mined
[2021-12-14T10:24:06Z INFO  farcaster_node::syncerd::syncer_state] Bitcoin incremented height 2131053
[2021-12-14T10:24:06Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx Lock final with 1 confirmations
[2021-12-14T10:24:06Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Send 0.492172460000 XMR to 58MrBmqaA1xgBiYZyEtYRtP6L5KgxwF8AWxGcZhgPqxuStqkHM2wde11bRNDJwD4KLgTXNy3HgQDXRLKv7KrVND2AHkkCqV
[2021-12-14T10:24:06Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching AccLock on address 58MrBmqaA1xgBiYZyEtYRtP6L5KgxwF8AWxGcZhgPqxuStqkHM2wde11bRNDJwD4KLgTXNy3HgQDXRLKv7KrVND2AHkkCqV
[2021-12-14T10:24:06Z INFO  farcaster_node::farcasterd::runtime] 0x892e…ddb0 | Attempting to auto-fund Monero
[2021-12-14T10:24:09Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985671
[2021-12-14T10:24:09Z WARN  farcaster_node::farcasterd::runtime] Server error: not enough unlocked money
[2021-12-14T10:24:09Z ERROR farcaster_node::farcasterd::runtime] 0x892e…ddb0 | Auto-funding Monero transaction failed, pushing to cli, use `swap-cli needs-funding Monero` to retrieve address and amount
[2021-12-14T10:27:54Z WARN  farcaster_node::syncerd::monero_syncer] wallet doesn't exist, generating a new wallet: Server error: Failed to open wallet
[2021-12-14T10:28:12Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Watching AccLock transaction (0b4d25d123e1d0b1917ba7319e2e5d6fbfd440fa570be8b5a7b171a0fba7108f)
[2021-12-14T10:28:12Z INFO  farcaster_node::farcasterd::runtime] 0x892e…ddb0 | Your Monero funding completed
[2021-12-14T10:28:14Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx AccLock on mempool but hasn't been mined
[2021-12-14T10:29:34Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985672
[2021-12-14T10:29:35Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx AccLock mined with 1 confirmations
[2021-12-14T10:31:09Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985673
[2021-12-14T10:31:10Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx AccLock mined with 2 confirmations
[2021-12-14T10:32:08Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985674
[2021-12-14T10:32:09Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx AccLock mined with 3 confirmations
[2021-12-14T10:33:35Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985675
[2021-12-14T10:33:36Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx AccLock mined with 4 confirmations
[2021-12-14T10:34:31Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985676
[2021-12-14T10:34:32Z INFO  farcaster_node::swapd::runtime] 0x892e…ddb0 | Tx AccLock final with 5 confirmations
[2021-12-14T10:34:54Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985677
[2021-12-14T10:36:04Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985678
[2021-12-14T10:40:56Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985679
[2021-12-14T10:43:19Z INFO  farcaster_node::syncerd::syncer_state] Bitcoin incremented height 2131054
[2021-12-14T10:43:45Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985680
[2021-12-14T10:44:57Z INFO  farcaster_node::syncerd::syncer_state] Monero incremented height 985681

Dec 14 '21 13:12 Lederstrumpf

from_height related? wallet not scanning height tx is in

Dec 14 '21 20:12 zkao