[Bug] swap user cannot connect to my ASB reliably via /ip4/ netaddr

[sethforprivacy]

When the swap user attempts to resume a swap with my ASB, as he is unable to specify netaddr his swap client defaults to using the original swap netaddr, /ip4/5.9.120.18/tcp/9939/p2p/12D3KooWCPcfhr6e7V7NHoKWRxZ5zPRr6v5hGrVPhHdsftQk2DXW.

When his client attempts to connect he gets disconnected and reconnected rapidly with the following logs (apologies for the images instead of text):

On my side, I see the following in logs:

2021-08-18 01:51:33 DEBUG New connection established peer=12D3KooWHhjef8D5QdAGr9yLJRXRMqMYeyeC6CS2yMvjaK5LxjUV address=/ip4/redacted/tcp/62976
2021-08-18 01:52:03  WARN Lost connection to peer: Connection error: Handler error: Connection closed due to expired keep-alive timeout. peer=12D3KooWHhjef8D5QdAGr9yLJRXRMqMYeyeC6CS2yMvjaK5LxjUV address=/ip4/redacted/tcp/62976
2021-08-18 01:52:06 DEBUG New connection established peer=12D3KooWHhjef8D5QdAGr9yLJRXRMqMYeyeC6CS2yMvjaK5LxjUV address=/ip4/redacted/tcp/62989
2021-08-18 01:52:36  WARN Lost connection to peer: Connection error: Handler error: Connection closed due to expired keep-alive timeout. peer=12D3KooWHhjef8D5QdAGr9yLJRXRMqMYeyeC6CS2yMvjaK5LxjUV address=/ip4/redacted/tcp/62989
2021-08-18 01:52:38 DEBUG New connection established peer=12D3KooWHhjef8D5QdAGr9yLJRXRMqMYeyeC6CS2yMvjaK5LxjUV address=/ip4/redacted/tcp/63013

And when running tcpdump -i enp35s0 src 141.98.103.251 and dst port 9939, I get the following during these failed attempts to connect:

root in node in ~ ❯ tcpdump -i enp35s0 src redacted and dst port 9939
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp35s0, link-type EN10MB (Ethernet), capture size 262144 bytes
03:11:52.192622 IP redacted.49362 > asb-server.9939: Flags [.], ack 653, win 6142, length 0
03:11:52.196863 IP redacted.49362 > asb-server.9939: Flags [P.], seq 574:576, ack 653, win 6142, length 2
03:11:52.196863 IP redacted.49362 > asb-server.9939: Flags [P.], seq 576:636, ack 653, win 6142, length 60
03:11:52.196863 IP redacted.49362 > asb-server.9939: Flags [P.], seq 636:638, ack 653, win 6142, length 2
03:11:52.196863 IP redacted.49362 > asb-server.9939: Flags [P.], seq 638:698, ack 653, win 6142, length 60
03:11:52.268796 IP redacted.49362 > asb-server.9939: Flags [.], ack 715, win 6142, length 0
03:12:07.268987 IP redacted.49362 > asb-server.9939: Flags [.], ack 716, win 6142, length 0
03:12:07.268987 IP redacted.49362 > asb-server.9939: Flags [F.], seq 698, ack 716, win 6142, length 0
03:12:07.605397 IP redacted.49362 > asb-server.9939: Flags [F.], seq 698, ack 716, win 6142, length 0
03:12:09.281200 IP redacted.49380 > asb-server.9939: Flags [S], seq 1029490900, win 64860, options [mss 1380,nop,wscale 8,nop,nop,sackOK], length 0
03:12:09.349358 IP redacted.49380 > asb-server.9939: Flags [.], ack 3569472580, win 6145, length 0
03:12:09.349358 IP redacted.49380 > asb-server.9939: Flags [P.], seq 0:28, ack 1, win 6145, length 28
03:12:09.415221 IP redacted.49380 > asb-server.9939: Flags [.], ack 29, win 6145, length 0
03:12:09.419188 IP redacted.49380 > asb-server.9939: Flags [P.], seq 28:30, ack 29, win 6145, length 2
03:12:09.419369 IP redacted.49380 > asb-server.9939: Flags [P.], seq 30:62, ack 29, win 6145, length 32
03:12:09.485325 IP redacted.49380 > asb-server.9939: Flags [.], ack 231, win 6144, length 0
03:12:09.489321 IP redacted.49380 > asb-server.9939: Flags [P.], seq 62:64, ack 231, win 6144, length 2
03:12:09.489321 IP redacted.49380 > asb-server.9939: Flags [P.], seq 64:232, ack 231, win 6144, length 168
03:12:09.489321 IP redacted.49380 > asb-server.9939: Flags [P.], seq 232:234, ack 231, win 6144, length 2
03:12:09.489512 IP redacted.49380 > asb-server.9939: Flags [P.], seq 234:284, ack 231, win 6144, length 50
03:12:09.555180 IP redacted.49380 > asb-server.9939: Flags [.], ack 269, win 6144, length 0
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [.], ack 369, win 6143, length 0
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [P.], seq 284:286, ack 369, win 6143, length 2
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [P.], seq 286:334, ack 369, win 6143, length 48
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [P.], seq 334:336, ack 369, win 6143, length 2
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [P.], seq 336:382, ack 369, win 6143, length 46
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [P.], seq 382:384, ack 369, win 6143, length 2
03:12:09.559783 IP redacted.49380 > asb-server.9939: Flags [P.], seq 384:450, ack 369, win 6143, length 66
03:12:09.633330 IP redacted.49380 > asb-server.9939: Flags [.], ack 419, win 6143, length 0
03:12:09.633492 IP redacted.49380 > asb-server.9939: Flags [P.], seq 450:452, ack 529, win 6143, length 2
03:12:09.633493 IP redacted.49380 > asb-server.9939: Flags [P.], seq 452:512, ack 529, win 6143, length 60
03:12:09.633493 IP redacted.49380 > asb-server.9939: Flags [P.], seq 512:514, ack 529, win 6143, length 2
03:12:09.633493 IP redacted.49380 > asb-server.9939: Flags [P.], seq 514:574, ack 529, win 6143, length 60
03:12:09.699190 IP redacted.49380 > asb-server.9939: Flags [.], ack 591, win 6143, length 0

All IP addresses for the user are redacted intentionally, of course.

Background information:

• When did this happen: Upon attempting to resume a trade that failed
• Versions: swap-0.8.1-preview, asb-0.8.1-preview
• Logs of failed trade:

2021-08-17 23:18:07  WARN Failed to get status of script: Failed to subscribe to header notifications: Made one or multiple attempts, all errored:
        - CloseNotify alert received
 txid=a629b1a4f39d63fcf551624f01e6847a8745e044fc10d569df2c6b793f3561d8
2021-08-17 23:18:07 ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Failed to monitor refund transaction
2021-08-17 23:18:07 ERROR Swap failed: Failed to monitor refund transaction: Failed while waiting for next status update: channel closed swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
2021-08-17 23:21:03  WARN Failed to relay encrypted signature to swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20

[thomaseizinger]

2021-08-18 01:52:03 WARN Lost connection to peer: Connection error: Handler error: Connection closed due to expired keep-alive timeout.

That is the important line. We seem to actively close the connection because of a keep-alive timeout. Can this issue be reproduced with other users as well?

[sethforprivacy]

2021-08-18 01:52:03 WARN Lost connection to peer: Connection error: Handler error: Connection closed due to expired keep-alive timeout.

That is the important line. We seem to actively close the connection because of a keep-alive timeout. Can this issue be reproduced with other users as well?

AFAICT most other users do not have issues -- I have had several successful swaps since this issue occurred, although I do see several other peers go through this connection loop in similar ways.

[sethforprivacy]

I had a user reach out who was one of the successful swap participants, but he also gets rapid disconnects/reconnects during the swap waiting periods with I/O error, connection is closed. repeatedly.

The swap still goes through, but the message spam certainly looks bad to swap users, if nothing else.

I've requested the logs from the user, but if there is anything else I can provide, please let me know!

[thomaseizinger]

Right, I'll see if there is an easy fix to it.

[gsee]

I'm the successful swap participant. Here are the logs from my terminal:
swap-log.txt

[sethforprivacy]

#649 seems to have resolved the log spam, at least, so I reached out to the known-failing swap partner to try it again.

[sethforprivacy]

The swap user was able to connect and attempt to resume the swap, but it failed with the following logs:

 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00564200 BTC
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Failed to monitor refund transaction
ERROR Swap failed: Failed to monitor refund transaction: Failed while waiting for next status update: channel closed swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00568200 BTC
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is punishable rate=0.00567700 BTC
 WARN swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Failed to publish punish transaction: Failed to broadcast Bitcoin punish transaction REDACTED: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-25,\"message\":\"bad-txns-inputs-missingorspent\"}")))
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Falling back to refund
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Electrum(Protocol(String("missing transaction")))
ERROR Swap failed: Electrum(Protocol(String("missing transaction"))) swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20

[thomaseizinger]

The swap user was able to connect and attempt to resume the swap, but it failed with the following logs:

 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00564200 BTC
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Failed to monitor refund transaction
ERROR Swap failed: Failed to monitor refund transaction: Failed while waiting for next status update: channel closed swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00568200 BTC
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is punishable rate=0.00567700 BTC
 WARN swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Failed to publish punish transaction: Failed to broadcast Bitcoin punish transaction REDACTED: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-25,\"message\":\"bad-txns-inputs-missingorspent\"}")))
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Falling back to refund
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Electrum(Protocol(String("missing transaction")))
ERROR Swap failed: Electrum(Protocol(String("missing transaction"))) swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20

Can you post the logs of the corresponding swap from the ASB? You should be able to find something with the same swap id.

[sethforprivacy]

The swap user was able to connect and attempt to resume the swap, but it failed with the following logs:

 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00564200 BTC
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Failed to monitor refund transaction
ERROR Swap failed: Failed to monitor refund transaction: Failed while waiting for next status update: channel closed swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00568200 BTC
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is punishable rate=0.00567700 BTC
 WARN swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Failed to publish punish transaction: Failed to broadcast Bitcoin punish transaction REDACTED: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-25,\"message\":\"bad-txns-inputs-missingorspent\"}")))
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Falling back to refund
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Electrum(Protocol(String("missing transaction")))
ERROR Swap failed: Electrum(Protocol(String("missing transaction"))) swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20

Can you post the logs of the corresponding swap from the ASB? You should be able to find something with the same swap id.

Those are the ASB logs, sorry if that wasn't clear! Swap client logs for the swap are here:

#651 (comment)

[ghost]

This was supposed to be fixed in 0.8.2, but I think still persists. Because I'm running 0.8.3 and this connection error has happened a lot. A lot!

[thomaseizinger]

Make sure whoever you are trading with, ie the ASB is running at least 0.8.2 as well!

[ghost]

Make sure whoever you are trading with, ie the ASB is running at least 0.8.2 as well!

I am the ASB. We have no control over what version the other side is using. It might be a good idea for the program itself to make sure the user is running the latest version?