search

ElementsProject / peerswap

MIT License
109 stars 40 forks source link

Crash during recovery #74

Closed wtogami closed 1 year ago

wtogami commented 2 years ago

After the crash documented in #73 subsequent peerswap startup crashed. It might be difficult to reproduce this state later so documenting it here as peerswap needs to be able to recover from weird states.

2022-06-03T10:56:18.851Z INFO    lightningd: --------------------------------------------------
2022-06-03T10:56:18.851Z INFO    lightningd: Server started with public key REDACTED, alias HONEYPOT (color #01dc50) and lightningd v0.10.2
2022-06-03T10:56:19.024Z INFO    plugin-peerswap-plugin: PeerSwap Initialized, running PeerSwap commit 1f0e91fe95b5e8124d035628cb91623fea462b50
2022-06-03T10:56:19.757Z INFO    plugin-peerswap-plugin: Liquid swaps enabled
2022-06-03T10:56:20.209Z INFO    plugin-peerswap-plugin: Bitcoin swaps enabled
2022-06-03T10:56:20.259Z INFO    plugin-peerswap-plugin: using policy:
2022-06-03T10:56:20.259Z INFO    plugin-peerswap-plugin: reserve_onchain_msat: 0
2022-06-03T10:56:20.259Z INFO    plugin-peerswap-plugin: allowlisted_peers: [REDACTED MANY PUBKEYS]
2022-06-03T10:56:20.260Z INFO    plugin-peerswap-plugin: accept_all_peers: false
2022-06-03T10:56:20.260Z INFO    plugin-peerswap-plugin:
2022-06-03T10:56:20.628Z INFO    plugin-peerswap-plugin: [Swap:6a0fbd775103b48e08ac7bf3e873637cc539442ee1a64d05710fcc62e4a37560]: Recovering from state State_SwapOutReceiver_AwaitClaimInvoicePayment
2022-06-03T10:56:20.640Z INFO    plugin-peerswap-plugin: peerswap initialized
2022-06-03T10:56:23.093Z DEBUG   plugin-peerswap-plugin: [Payment Notifier] Error 903:invoice expired during wait
2022-06-03T10:56:35.585Z DEBUG   plugin-peerswap-plugin: [FSM] event:id: 6a0fbd775103b48e08ac7bf3e873637cc539442ee1a64d05710fcc62e4a37560, Event_OnCsvPassed on State_SwapOutReceiver_AwaitClaimInvoicePayment
2022-06-03T10:56:36.524Z INFO    plugin-peerswap-plugin: Killing plugin: exited during normal operation
fatal: morestack on g0
SIGTRAP: trace trap
PC=0x466a02 m=4 sigcode=128
signal arrived during cgo execution

goroutine 46 [syscall]:
runtime.cgocall(0x7069f0, 0xc0001d1328)
    /usr/local/src/runtime/cgocall.go:157 +0x5c fp=0xc0001d1300 sp=0xc0001d12c8 pc=0x4078bc
github.com/vulpemventures/go-secp256k1-zkp._Cfunc_secp256k1_context_create(0x301)
    _cgo_gotypes.go:298 +0x4d fp=0xc0001d1328 sp=0xc0001d1300 pc=0x6bd0cd
github.com/vulpemventures/go-secp256k1-zkp.ContextCreate(0x301)
    /root/go/pkg/mod/github.com/vulpemventures/go-secp256k1-zkp@v1.1.5/secp256k1.go:74 +0x37 fp=0xc0001d1350 sp=0xc0001d1328 pc=0x6c1817
github.com/vulpemventures/go-elements/confidential.nonceHash({0xc0005ac900, 0x21, 0x30}, {0xc000490f20, 0x20, 0x20})
    /root/go/pkg/mod/github.com/vulpemventures/go-elements@v0.3.7/confidential/confidential.go:175 +0x7b fp=0xc0001d13d0 sp=0xc0001d1350 pc=0x6c2bdb
github.com/vulpemventures/go-elements/confidential.NonceHash(...)
    /root/go/pkg/mod/github.com/vulpemventures/go-elements@v0.3.7/confidential/confidential.go:16
github.com/vulpemventures/go-elements/confidential.UnblindOutputWithKey(0xc0002283f0, {0xc000490f20?, 0x3?, 0x90?})
    /root/go/pkg/mod/github.com/vulpemventures/go-elements@v0.3.7/confidential/confidential.go:39 +0x6a fp=0xc0001d1470 sp=0xc0001d13d0 pc=0x6c2a8a
github.com/elementsproject/peerswap/onchain.(*LiquidOnChain).createSpendingTransaction(0xc0004b2540, {0xc0005c1000, 0x45f4}, 0x186a0, 0x3c, {0xc0004f01b0, 0x21, 0x30}, {0xc0005d5a00, 0x98, ...}, ...)
    /opt/plugins/ps/onchain/liquid.go:273 +0x230 fp=0xc0001d19d0 sp=0xc0001d1470 pc=0x6cd610
github.com/elementsproject/peerswap/onchain.(*LiquidOnChain).prepareSpendingTransaction(0xc0004b2540, 0xc00049d4f0, 0xc0001aa380, {0xc0000c4540, 0x65}, 0x68?, 0x7f0bc17d85b8?)
    /opt/plugins/ps/onchain/liquid.go:246 +0x1b0 fp=0xc0001d1b20 sp=0xc0001d19d0 pc=0x6cd250
github.com/elementsproject/peerswap/onchain.(*LiquidOnChain).CreateCsvSpendingTransaction(0xc0004b2540, 0x7a6583?, 0x40?)
    /opt/plugins/ps/onchain/liquid.go:164 +0xad fp=0xc0001d1bf8 sp=0xc0001d1b20 pc=0x6cc2ad
github.com/elementsproject/peerswap/swap.(*ClaimSwapTransactionWithCsv).Execute(0xc000211200?, 0xc00057a1c0?, 0xc0005b2480)
    /opt/plugins/ps/swap/actions.go:410 +0x94 fp=0xc0001d1c40 sp=0xc0001d1bf8 pc=0x6a02d4
github.com/elementsproject/peerswap/swap.StopSendMessageWithRetryWrapperAction.Execute({{0x95c8a0?, 0xb872e0?}}, 0xc0000bc2a0, 0xc0005b2480)
    /opt/plugins/ps/swap/actions.go:260 +0xd0 fp=0xc0001d1c80 sp=0xc0001d1c40 pc=0x69eeb0
github.com/elementsproject/peerswap/swap.(*StopSendMessageWithRetryWrapperAction).Execute(0xc0005b0150?, 0xc0004f7fb0?, 0x7b493b?)
    <autogenerated>:1 +0x3d fp=0xc0001d1cb0 sp=0xc0001d1c80 pc=0x6b567d
github.com/elementsproject/peerswap/swap.(*SwapStateMachine).SendEvent(0xc0005b0150, {0x7ab008, 0x11}, {0x0?, 0x0})
    /opt/plugins/ps/swap/fsm.go:187 +0x6f4 fp=0xc0001d1da0 sp=0xc0001d1cb0 pc=0x6a2a34
github.com/elementsproject/peerswap/swap.(*SwapService).OnCsvPassed(0x40?, {0xc0005d04c0?, 0xc000660840?})
    /opt/plugins/ps/swap/service.go:297 +0x4d fp=0xc0001d1e28 sp=0xc0001d1da0 pc=0x6a734d
github.com/elementsproject/peerswap/swap.(*SwapService).OnCsvPassed-fm({0xc0005d04c0?, 0xc00057b040?})
    <autogenerated>:1 +0x34 fp=0xc0001d1e50 sp=0xc0001d1e28 pc=0x6b4fd4
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).HandleCsvTx(0xc0004a4c60, 0xc00003df80?)
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:195 +0x194 fp=0xc0001d1f48 sp=0xc0001d1e50 pc=0x6e8ab4
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1()
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:102 +0xf4 fp=0xc0001d1fd0 sp=0xc0001d1f48 pc=0x6e8094
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func3()
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:110 +0x24 fp=0xc0001d1fe0 sp=0xc0001d1fd0 pc=0x6e7f64
runtime.goexit()
    /usr/local/src/runtime/asm_amd64.s:1571 +0x1 fp=0xc0001d1fe8 sp=0xc0001d1fe0 pc=0x466ba1
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:86 +0x15b

goroutine 1 [chan receive]:
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 8 [syscall]:
syscall.Syscall(0x0, 0x0, 0xc0000da400, 0x400)
    /usr/local/src/syscall/asm_linux_amd64.s:20 +0x5
syscall.read(0xc00006c060?, {0xc0000da400?, 0x41b54b?, 0x7f0b9acb6f00?})
    /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(0xc00006c060?, {0xc0000da400?, 0x400?, 0x400?})
    /usr/local/src/internal/poll/fd_unix.go:163 +0x285
os.(*File).read(...)
    /usr/local/src/os/file_posix.go:31
os.(*File).Read(0xc000010010, {0xc0000da400?, 0xc00003d588?, 0x46fa46?})
    /usr/local/src/os/file.go:119 +0x5e
bufio.(*Scanner).Scan(0xc00003d688)
    /usr/local/src/bufio/scan.go:215 +0x865
github.com/elementsproject/glightning/jrpc2.(*Server).listen(0xc00006a280, {0x95cf60?, 0xc000010010?})
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/server.go:108 +0xef
github.com/elementsproject/glightning/jrpc2.(*Server).StartUp(0xc00006a280, 0xc0004b2040?, 0xc000010018)
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/server.go:69 +0xa7
github.com/elementsproject/glightning/glightning.(*Plugin).Start(0xc000090000, 0x0?, 0x0?)
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/glightning/plugin.go:1294 +0x149
github.com/elementsproject/peerswap/clightning.(*ClightningClient).Start(...)
    /opt/plugins/ps/clightning/clightning.go:200
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 18 [select]:
io.(*pipe).read(0xc0004a4000, {0xc0000ba000, 0x1000, 0x1?})
    /usr/local/src/io/pipe.go:57 +0xb1
io.(*PipeReader).Read(0x0?, {0xc0000ba000?, 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({0x95cc40?, 0xc0004a6000?}, 0xc000090000)
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/glightning/plugin.go:1327 +0xaf
created by github.com/elementsproject/glightning/glightning.(*Plugin).checkForMonkeyPatch
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/glightning/plugin.go:1324 +0x27b

goroutine 19 [chan receive]:
github.com/elementsproject/glightning/jrpc2.(*Server).setupWriteQueue(0xc00006a280, {0x95cf80?, 0xc000010018?})
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/server.go:132 +0x125
created by github.com/elementsproject/glightning/jrpc2.(*Server).StartUp
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/server.go:68 +0x91

goroutine 9 [chan receive]:
github.com/elementsproject/glightning/jrpc2.(*Client).setupWriteQueue(0xc0000760a0, {0x7f0b9aa3d198?, 0xc000010360?})
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/client.go:91 +0x165
github.com/elementsproject/glightning/jrpc2.(*Client).SocketStart(0xc0000760a0, {0xc0000266f0, 0x26}, 0xc0000802a0)
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/client.go:64 +0x1c5
github.com/elementsproject/glightning/glightning.(*Lightning).StartUp.func1(0xc000021150, {0xc00002cee0?, 0x665192?}, {0xc000028288?, 0xc0000da800?}, 0x3ac?, 0x3ac?)
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/glightning/lightning.go:34 +0x85
created by github.com/elementsproject/glightning/glightning.(*Lightning).StartUp
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/glightning/lightning.go:33 +0x165

goroutine 10 [IO wait]:
internal/poll.runtime_pollWait(0x7f0b9aa3b758, 0x72)
    /usr/local/src/runtime/netpoll.go:302 +0x89
internal/poll.(*pollDesc).wait(0xc000022480?, 0xc0003b8002?, 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(0xc000022480, {0xc0003b8002, 0x7fdfe, 0x7fdfe})
    /usr/local/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000022480, {0xc0003b8002?, 0xc000629950?, 0x203000?})
    /usr/local/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc000010360, {0xc0003b8002?, 0xc0003b8000?, 0xc000239ee0?})
    /usr/local/src/net/net.go:183 +0x45
encoding/json.(*Decoder).refill(0xc0000e0280)
    /usr/local/src/encoding/json/stream.go:165 +0x17f
encoding/json.(*Decoder).readValue(0xc0000e0280)
    /usr/local/src/encoding/json/stream.go:140 +0xbb
encoding/json.(*Decoder).Decode(0xc0000e0280, {0x74d8c0, 0xc000204d20})
    /usr/local/src/encoding/json/stream.go:63 +0x78
github.com/elementsproject/glightning/jrpc2.(*Client).readQueue(0xc0000760a0, {0x95cd80?, 0xc000010360})
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/client.go:113 +0xab
github.com/elementsproject/glightning/jrpc2.(*Client).SocketStart.func1({0x9604d8?, 0xc000010360}, 0x3ac?)
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/client.go:62 +0x6b
created by github.com/elementsproject/glightning/jrpc2.(*Client).SocketStart
    /root/go/pkg/mod/github.com/elementsproject/glightning@v0.0.0-20220502095901-74f998c51367/jrpc2/client.go:58 +0x19e

goroutine 45 [select]:
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartBlockWatcher(0xc0004a4c60, 0x1c675c)
    /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 47 [select]:
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartBlockWatcher(0xc00006cb40, 0xb472a)
    /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 48 [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 448 [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:417 +0x35
created by github.com/elementsproject/peerswap/clightning.(*ClightningClient).OnConnect
    /opt/plugins/ps/clightning/clightning.go:415 +0x72

goroutine 416 [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:417 +0x35
created by github.com/elementsproject/peerswap/clightning.(*ClightningClient).OnConnect
    /opt/plugins/ps/clightning/clightning.go:415 +0x72

goroutine 468 [semacquire]:
sync.runtime_SemacquireMutex(0x655880?, 0x20?, 0xc00062fec0?)
    /usr/local/src/runtime/sema.go:71 +0x25
sync.(*Mutex).lockSlow(0xc0004a4cb0)
    /usr/local/src/sync/mutex.go:162 +0x165
sync.(*Mutex).Lock(...)
    /usr/local/src/sync/mutex.go:81
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).HandleConfirmedTx(0xc0004a4c60, 0xc00063fc20?)
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:141 +0x52
github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1.1()
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:96 +0x25
created by github.com/elementsproject/peerswap/txwatcher.(*BlockchainRpcTxWatcher).StartWatchingTxs.func1
    /opt/plugins/ps/txwatcher/rpctxwatcher.go:95 +0xe5

goroutine 220 [select]:
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

rax    0x17
rbx    0x7ae43c
rcx    0x4683d5
rdx    0x17
rdi    0x2
rsi    0x7ae43c
rbp    0x5de5
rsp    0x7f0b9ab0c2e8
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
nepet commented 2 years ago

Just for reference: The logs of #73 and #74 are mixed up. The panic log in #73 is the recovery crash.

nepet commented 2 years ago

I asked vulpem ventures for help on this crash as it seems that the cgo call for secp256k1 crashed and I dont know why vulpemventures/go-elements#203