Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CLN: peerswap-plugin crash after self fails to pay swap invoice #67

Closed
wtogami opened this issue Jun 1, 2022 · 2 comments
Closed

CLN: peerswap-plugin crash after self fails to pay swap invoice #67

wtogami opened this issue Jun 1, 2022 · 2 comments
Assignees
@nepet
Labels
bug Something isn't working
Milestone
v0.3.0

Comments

@wtogami
Copy link
Contributor

wtogami commented Jun 1, 2022

Responder: CLN v0.10.2 peerswap 2833bdb
Requester: LND v0.14.1-beta peerswap 9fb06e1

Sequence of Events

  • 22 min 56 sec LND requested swap-in 1000000 <SHORTID> lbtc.
  • Immediately thereafter the LND node went nuts starting 34,000 extraneous invoice subscriptions (fixed in lnd: stop oversubscribing to invoice and tx events #65 and Fix lnd payment notifier #66).
  • 24 min 35 sec peerswap-plugin crashes on the CLN side.
  • 32 min 56 sec LND peerswapd goes into State_SwapInSender_AwaitClaimPayment after failing to see an incoming LN payment then timing out.
  • 1 hour 22 min CSV timed out so onchain funds reclaimed.

CLN peerswap log messages:

2022-05-30T19:22:56.913Z INFO    plugin-peerswap-plugin: [Swap:e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68] swap in request received: peer: REDACTED chanId: REDACTED:REDACTED:1 initiator: REDACTED amount 1000000
2022-05-30T19:24:35.890Z INFO    plugin-peerswap-plugin: Killing plugin: exited during normal operation

CLN peerswap-plugin peerswap-panic-log:

fatal: morestack on g0
SIGTRAP: trace trap
PC=0x466a02 m=4 sigcode=128
signal arrived during cgo execution

goroutine 410033 [syscall]:
runtime.cgocall(0x706cf0, 0xc0004939f8)
	/usr/local/src/runtime/cgocall.go:157 +0x5c fp=0xc0004939d0 sp=0xc000493998 pc=0x4078bc
github.com/vulpemventures/go-secp256k1-zkp._Cfunc_secp256k1_context_create(0x301)
	_cgo_gotypes.go:298 +0x4d fp=0xc0004939f8 sp=0xc0004939d0 pc=0x6bd32d
github.com/vulpemventures/go-secp256k1-zkp.ContextCreate(0x301)
	/root/go/pkg/mod/github.com/vulpemventures/[email protected]/secp256k1.go:74 +0x37 fp=0xc000493a20 sp=0xc0004939f8 pc=0x6c1a77
github.com/vulpemventures/go-elements/confidential.nonceHash({0xc0000261b0, 0x21, 0x30}, {0xc000098b00, 0x20, 0x20})
	/root/go/pkg/mod/github.com/vulpemventures/[email protected]/confidential/confidential.go:175 +0x7b fp=0xc000493aa0 sp=0xc000493a20 pc=0x6c2e3b
github.com/vulpemventures/go-elements/confidential.NonceHash(...)
	/root/go/pkg/mod/github.com/vulpemventures/[email protected]/confidential/confidential.go:16
github.com/vulpemventures/go-elements/confidential.UnblindOutputWithKey(0xc0000d1050, {0xc000098b00?, 0x2?, 0xc00002aac0?})
	/root/go/pkg/mod/github.com/vulpemventures/[email protected]/confidential/confidential.go:39 +0x6a fp=0xc000493b40 sp=0xc000493aa0 pc=0x6c2cea
github.com/elementsproject/peerswap/onchain.(*LiquidOnChain).ValidateTx(0xc00006a300, 0xc0000760f0, {0xc000016a00, 0x23d6})
	/opt/plugins/ps/onchain/liquid.go:434 +0x112 fp=0xc000493bf8 sp=0xc000493b40 pc=0x6ceff2
github.com/elementsproject/peerswap/swap.(*ValidateTxAndPayClaimInvoiceAction).Execute(0xc0004e0070?, 0xc0001f01c0, 0xc00017a300)
	/opt/plugins/ps/swap/actions.go:642 +0xdb fp=0xc000493cf0 sp=0xc000493bf8 pc=0x6a1c9b
github.com/elementsproject/peerswap/swap.(*SwapStateMachine).SendEvent(0xc0004e0070, {0x7ac118, 0x13}, {0x0?, 0x0})
	/opt/plugins/ps/swap/fsm.go:187 +0x6f4 fp=0xc000493de0 sp=0xc000493cf0 pc=0x6a2c94
github.com/elementsproject/peerswap/swap.(*SwapService).OnTxConfirmed(0xc00014a000?, {0xc0002c2100?, 0x40?}, {0xc000016a00, 0x23d6})
	/opt/plugins/ps/swap/service.go:279 +0xa5 fp=0xc000493e68 sp=0xc000493de0 pc=0x6a73c5
github.com/elementsproject/peerswap/swap.(*SwapService).OnTxConfirmed-fm({0xc0002c2100?, 0xc00031e7b0?}, {0xc000016a00?, 0x40?})
	<autogenerated>:1 +0x3f fp=0xc000493ea0 sp=0xc000493e68 pc=0x6b519f
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).HandleConfirmedTx(0xc0000acd20, 0xc00045c0c0?)
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:163 +0x1b0 fp=0xc000493f98 sp=0xc000493ea0 pc=0x6e89b0
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1.1()
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:96 +0x25 fp=0xc000493fe0 sp=0xc000493f98 pc=0x6e8445
runtime.goexit()
	/usr/local/src/runtime/asm_amd64.s:1571 +0x1 fp=0xc000493fe8 sp=0xc000493fe0 pc=0x466ba1
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:95 +0xe5

goroutine 1 [chan receive, 1063 minutes]:
main.run()
	/opt/plugins/ps/cmd/peerswap-plugin/main.go:259 +0x10e5
main.main()
	/opt/plugins/ps/cmd/peerswap-plugin/main.go:55 +0xe5

goroutine 6 [syscall]:
syscall.Syscall(0x0, 0x0, 0xc0002890ce, 0xf32)
	/usr/local/src/syscall/asm_linux_amd64.s:20 +0x5
syscall.read(0xc0000ac000?, {0xc0002890ce?, 0x41b54b?, 0x7f8c15320400?})
	/usr/local/src/syscall/zsyscall_linux_amd64.go:696 +0x4d
syscall.Read(...)
	/usr/local/src/syscall/syscall_unix.go:188
internal/poll.ignoringEINTRIO(...)
	/usr/local/src/internal/poll/fd_unix.go:794
internal/poll.(*FD).Read(0xc0000ac000?, {0xc0002890ce?, 0xf32?, 0xf32?})
	/usr/local/src/internal/poll/fd_unix.go:163 +0x285
os.(*File).read(...)
	/usr/local/src/os/file_posix.go:31
os.(*File).Read(0xc0000aa000, {0xc0002890ce?, 0xc00069bd88?, 0x46fa46?})
	/usr/local/src/os/file.go:119 +0x5e
bufio.(*Scanner).Scan(0xc00069be88)
	/usr/local/src/bufio/scan.go:215 +0x865
github.com/elementsproject/glightning/jrpc2.(*Server).listen(0xc0000ee240, {0x95d100?, 0xc0000aa000?})
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/server.go:108 +0xef
github.com/elementsproject/glightning/jrpc2.(*Server).StartUp(0xc0000ee240, 0xc0000eea00?, 0xc0000aa008)
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/server.go:69 +0xa7
github.com/elementsproject/glightning/glightning.(*Plugin).Start(0xc0004e0000, 0x0?, 0x0?)
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/glightning/plugin.go:1294 +0x149
github.com/elementsproject/peerswap/clightning.(*ClightningClient).Start(...)
	/opt/plugins/ps/clightning/clightning.go:210
main.run.func1()
	/opt/plugins/ps/cmd/peerswap-plugin/main.go:83 +0x3d
created by main.run
	/opt/plugins/ps/cmd/peerswap-plugin/main.go:82 +0x13f

goroutine 7 [select, 1063 minutes]:
io.(*pipe).read(0xc0000ac480, {0xc000159000, 0x1000, 0x0?})
	/usr/local/src/io/pipe.go:57 +0xb1
io.(*PipeReader).Read(0x0?, {0xc000159000?, 0x0?, 0x0?})
	/usr/local/src/io/pipe.go:136 +0x25
bufio.(*Scanner).Scan(0xc000051f28)
	/usr/local/src/bufio/scan.go:215 +0x865
github.com/elementsproject/glightning/glightning.(*Plugin).checkForMonkeyPatch.func1({0x95cde0?, 0xc0000100c0?}, 0xc0004e0000)
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/glightning/plugin.go:1327 +0xaf
created by github.com/elementsproject/glightning/glightning.(*Plugin).checkForMonkeyPatch
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/glightning/plugin.go:1324 +0x27b

goroutine 8 [chan receive]:
github.com/elementsproject/glightning/jrpc2.(*Server).setupWriteQueue(0xc0000ee240, {0x95d120?, 0xc0000aa008?})
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/server.go:132 +0x125
created by github.com/elementsproject/glightning/jrpc2.(*Server).StartUp
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/server.go:68 +0x91

goroutine 20 [chan receive]:
github.com/elementsproject/glightning/jrpc2.(*Client).setupWriteQueue(0xc0000ae050, {0x7f8c150f82d8?, 0xc0000aa040?})
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/client.go:91 +0x165
github.com/elementsproject/glightning/jrpc2.(*Client).SocketStart(0xc0000ae050, {0xc0000b6690, 0x26}, 0xc000080420)
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/client.go:64 +0x1c5
github.com/elementsproject/glightning/glightning.(*Lightning).StartUp.func1(0xc000091140, {0xc00009a350?, 0x665192?}, {0xc0000cc258?, 0xc0000f8800?}, 0x3c8?, 0x3c8?)
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/glightning/lightning.go:34 +0x85
created by github.com/elementsproject/glightning/glightning.(*Lightning).StartUp
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/glightning/lightning.go:33 +0x165

goroutine 21 [IO wait]:
internal/poll.runtime_pollWait(0x7f8c150837d8, 0x72)
	/usr/local/src/runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc000092400?, 0xc0003c0002?, 0x0)
	/usr/local/src/internal/poll/fd_poll_runtime.go:83 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0xc000092400, {0xc0003c0002, 0x7fdfe, 0x7fdfe})
	/usr/local/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000092400, {0xc0003c0002?, 0xc00031ee10?, 0x203000?})
	/usr/local/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc0000aa040, {0xc0003c0002?, 0xc0003c0000?, 0xc000495ee0?})
	/usr/local/src/net/net.go:183 +0x45
encoding/json.(*Decoder).refill(0xc0000fe280)
	/usr/local/src/encoding/json/stream.go:165 +0x17f
encoding/json.(*Decoder).readValue(0xc0000fe280)
	/usr/local/src/encoding/json/stream.go:140 +0xbb
encoding/json.(*Decoder).Decode(0xc0000fe280, {0x74d9c0, 0xc0003521b0})
	/usr/local/src/encoding/json/stream.go:63 +0x78
github.com/elementsproject/glightning/jrpc2.(*Client).readQueue(0xc0000ae050, {0x95cf20?, 0xc0000aa040})
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/client.go:113 +0xab
github.com/elementsproject/glightning/jrpc2.(*Client).SocketStart.func1({0x960678?, 0xc0000aa040}, 0x3c8?)
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/client.go:62 +0x6b
created by github.com/elementsproject/glightning/jrpc2.(*Client).SocketStart
	/root/go/pkg/mod/github.com/elementsproject/[email protected]/jrpc2/client.go:58 +0x19e

goroutine 44 [sleep]:
time.Sleep(0x5f5e100)
	/usr/local/src/runtime/time.go:194 +0x12e
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1()
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:107 +0x135
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:86 +0x15b

goroutine 43 [select]:
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartBlockWatcher(0xc00006cba0, 0xb44c5)
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:120 +0xf6
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:85 +0xc9

goroutine 41 [select]:
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartBlockWatcher(0xc0000acd20, 0x1c4eb6)
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:120 +0xf6
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:85 +0xc9

goroutine 42 [semacquire]:
sync.runtime_SemacquireMutex(0x44a1fa?, 0xa0?, 0xc000457c20?)
	/usr/local/src/runtime/sema.go:71 +0x25
sync.(*Mutex).lockSlow(0xc0000acd70)
	/usr/local/src/sync/mutex.go:162 +0x165
sync.(*Mutex).Lock(...)
	/usr/local/src/sync/mutex.go:81
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).HandleCsvTx(0xc0000acd20, 0x1c52de?)
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:179 +0x52
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1()
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:102 +0xf4
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs
	/opt/plugins/ps/txwatcher/rpctxwatcher.go:86 +0x15b

goroutine 409371 [select, 2 minutes]:
github.com/elementsproject/peerswap/timer.TimedCallback({0x95f870, 0xc000444ac0}, 0x635?, 0xc000184ac0)
	/opt/plugins/ps/timer/timer.go:11 +0x8e
created by github.com/elementsproject/peerswap/swap.(*timeOutService).addNewTimeOut
	/opt/plugins/ps/swap/timeout.go:22 +0xb9

goroutine 214 [select, 43 minutes]:
github.com/elementsproject/peerswap/poll.(*Service).Start.func1()
	/opt/plugins/ps/poll/service.go:89 +0xa5
created by github.com/elementsproject/peerswap/poll.(*Service).Start
	/opt/plugins/ps/poll/service.go:87 +0x5b

goroutine 409985 [sleep]:
time.Sleep(0x2540be400)
	/usr/local/src/runtime/time.go:194 +0x12e
github.com/elementsproject/peerswap/clightning.(*ClightningClient).OnConnect.func1()
	/opt/plugins/ps/clightning/clightning.go:427 +0x35
created by github.com/elementsproject/peerswap/clightning.(*ClightningClient).OnConnect
	/opt/plugins/ps/clightning/clightning.go:425 +0x72

rax    0x17
rbx    0x7ae5d0
rcx    0x4683d5
rdx    0x17
rdi    0x2
rsi    0x7ae5d0
rbp    0x5de5
rsp    0x7f8c151822e8
r8     0x625295ed0
r9     0x54b451c2dd668
r10    0x38b0684
r11    0x246
r12    0x1311edb5f1895b
r13    0xdd84880
r14    0xc000003520
r15    0xcfdfcc60
rip    0x466a02
rflags 0x206
cs     0x33
fs     0x0
gs     0x0

CLN listswaps ending state

  {
      "id": "e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68",
      "asset": "lbtc",
      "created_at": "2022-05-30 19:22:56 +0000 UTC",
      "type": "swap in",
      "role": "receiver",
      "state": "State_SwapCanceled",
      "initiator_node_id": "REDACTED",
      "peer_node_id": "REDACTED",
      "amount": 1000000,
      "short_channel_id": "REDACTED:REDACTED:1",
      "opening_tx_id": "REDACTED",
      "cancel_message": "exceeded csv limit"
   }

LND lnd.log

2022-05-30 19:22:57.257 [INF] INVC: New single invoice subscription client: id=0, ref=(pay_hash=3b3dae67398a2dcd4f9899e39409d9a1ef0459c7762cb2aad691ad60d1b0e617)
2022-05-30 19:22:57.361 [INF] INVC: New single invoice subscription client: id=1, ref=(pay_hash=3b3dae67398a2dcd4f9899e39409d9a1ef0459c7762cb2aad691ad60d1b0e617)
... <same thing 34,000 times ...>

LND peerswap.log

2022/05/30 14:22:56 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_SwapInSender_OnSwapInRequested on
2022/05/30 14:22:56 [INFO] [Swap:e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68] Start new swap in: peer: REDACTEDPEER chanId: REDACTED:REDACTED:1 initiator: REDACTED amount 1000000
2022/05/30 14:22:56 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_ActionSucceeded on State_SwapInSender_CreateSwap
2022/05/30 14:22:56 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_ActionSucceeded on State_SwapInSender_SendRequest
2022/05/30 14:22:56 [DEBUG] [Messenger] From: REDACTEDPEER got msgtype: a459 payload: {"protocol_version":2,"swap_id":"e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68","pubkey":"REDACTED","premium":0}
2022/05/30 14:22:56 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_SwapInSender_OnAgreementReceived on State_SwapInSender_AwaitAgreement
2022/05/30 14:22:57 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_ActionSucceeded on State_SwapInSender_BroadcastOpeningTx
2022/05/30 14:22:57 [DEBUG] [RedundantSender] start sending messages of type 42077 to REDACTEDPEER
2022/05/30 14:22:57 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_ActionSucceeded on State_SwapInSender_SendTxBroadcastedMessage
2022/05/30 14:32:56 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_OnTimeout on State_SwapInSender_AwaitClaimPayment
2022/05/30 15:22:35 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_OnCsvPassed on State_SwapInSender_AwaitClaimPayment
2022/05/30 15:22:35 [DEBUG] [RedundantSender] stop sending messages of type 42077 to REDACTEDPEER
2022/05/30 15:22:35 [DEBUG] [FSM] event:id: e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68, Event_ActionSucceeded on State_SwapInSender_ClaimSwapCsv
2022/05/30 15:22:35 [INFO] [Swap:e2d5df28e680638875ede8474ffd04c207fb407f2d2fd68a9a427696abe67d68] Swap claimed by csv cooperatively

Why did CLN PeerSwap crash?

It is unclear whether LND peerswapd oversubscription problem #65 and #66 is wholly unrelated, or it exposed an edge case that led to the CLN peerswap-plugin crash.

My theory is it bogged down the LND node so severely that CLN failed to communicate over the TCP connection eventually leading to this peerswap-plugin crash.
@wtogami wtogami added the bug Something isn't working label Jun 1, 2022
@wtogami wtogami changed the title CLN: peerswap-plugin crash during requested lbtc swap-in CLN: rare peerswap-plugin crash during requested lbtc swap-in Jun 1, 2022
@wtogami wtogami changed the title CLN: rare peerswap-plugin crash during requested lbtc swap-in CLN: peerswap-plugin crash after self fails to pay swap invoice Jun 3, 2022
@wtogami wtogami added this to the v0.3.0 milestone Jun 3, 2022
@nepet nepet self-assigned this Jun 27, 2022
@nepet
Copy link
Contributor

nepet commented Jun 27, 2022

This might be connected to #73

@nepet nepet mentioned this issue Jul 11, 2022
Merged
@nepet nepet linked a pull request Jul 11, 2022 that will close this issue
Test for basic recovery #97
Merged
@nepet nepet removed a link to a pull request Jul 17, 2022
Test for basic recovery #97
Merged
@wtogami
Copy link
Contributor Author

wtogami commented Jul 14, 2023

We had a lot of fixes since this, some of which would prevent getting to this state. We haven't seen anything like this in more than a year. Closing for now.

@wtogami wtogami closed this as completed Jul 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nepet nepet

Labels
bug Something isn't working
Projects
None yet
Milestone
v0.3.0
Development

No branches or pull requests
2 participants
@wtogami @nepet