xud is unable to shutdown gracefully #1668
Comments
ghost
added
the
|
I also noticed that in our security tests Alice is unable to to shutdown gracefully: |
|
In another non-graceful shutdown (which was eventually killed by the 3 min docker timeout) I observed xud continuing to connect to peers: |
|
Saw the same today: that defitely increase travis runtime. |
|
can be easily reproducible with combined setup and buy ETH/BTC trade.
|
|
I would like to take a look at this if that's okay for you guys? |
|
I tried a few scenarios (simnet stop/start during when xud working, don't unlock, don't wait fully initialization) but I couldn't reproduce this, could you please step by step explain how to reproduce? |
Try a swap that fails/times out. |
|
Okay, at the first glance it looks like as an grpc client lndclient hangs when a swap fails/times out or if we shutdown xud during a swap (as soon as swap starts for example). Xud hangs in these situations because of a hanged up socket (with ESTABLISHED statement). At first I tried to find a way to listen grpc status and implement a complicated logic to shutdown gracefully, but in the end we're already shutting down gracefully only problem is a TCP socket with ESTABLISHED statement, and nobody actually listens it. So I suggest a very simple solution, can we call |
Can you link to the code you believe is preventing the shutdown? Perhaps we can clean up the listener? |
This actually happens on underlying socket, so when we call this xud/lib/lndclient/LndClient.ts Line 210 in 2ff63b9 we think everything is okay, actually everything must be okay, but somehow GRPC fails to switch outgoing TCP port to CLOSED and it hangs on ESTABLISHED if there's a failed swap or an ongoing swap. You can try yourself by taking xud stuck statement and checking which port is on use by node. For mac;
And you'll see that there's a random port is ESTABLISHED with 30009 (in my case with lndbtc) As soon as you stop lndbtc in this case, XUD shutdown too |
|
What do you guys think? |
|
That wasn't the case for my own trials, that somehow there's another case with P2P which prevents shutdown, is there a way to reproduce easily? |
|
start an older xud with tons of previously connected peers, best an old simnet xud, then immediately shutdown |
|
Unfortunately I couldn't understand, don't know what you mean by "older xud" with current code base can you give me an environment that I can reproduce and see what's happening? |
|
Sure, my simnet environment is in that state, I bet if you keep your environment online for some days and @raladev does his testing with tons of new simnet environments you'll get manya dead peers like me above and problems to shutdown too. |
|
Oh gotcha, will keep my xud open :) |
|
After a few days my xud failed to shutdown but there was no logs at all after gracefully shutdown log. Just the open ports, and seems like both connext & lnd connections failed to close. I'll try a few stuff. |
|
I tried to kill docker containers when xud stuck on shutdown but it still failed to shutdown 🤔 Just a quick question: was xud successfully shutting down before connext implementation, anyone remember? |
|
That's really hard to tell. But why just not disable connext and see where that gets you? |
|
Actually stucking on shutdown happens randomly so it's really hard to find out by disabling connext now, I checked ports as soon as I closed docker containers, there were no bound port, :/ I'll check how we integrate connext and what are the listeners that could cause such an issue on a spare time |
|
Update This definitely can be related with connext, just now connext started to throw 500 and I tried to stop xud but it didn't gracefully shutdown so I killed my docker process and suddenly xud shutdown too with the following logs:
|
|
Update: With a very small test that uses eventemitter of nodejs as we do in the xud, I tried to send CTRL+C, and program shutdowns gracefully, so this cant be happening because of our internal listeners: Output: |
|
Since I do not have a single clean shutdown these days, could it be as simple as xud continuing wiht p2p connection attempts even though the shutdown procedure should prevent that? All my xud shutdown logs look like this: https://paste.ubuntu.com/p/VnrZPBXcGH/ @LePremierHomme @sangaman @erkarl @rsercano |
|
Well after @sangaman's suggestion I checked once again and seems like there're multiple listeners still while closing, I'm creating a PR to remove them for server (p2p) and httpserver, let's discuss there. |
rsercano
added a commit
that referenced
this issue
Oct 23, 2020
|
Can you take over looking into this in parallel? @LePremierHomme |
raladev
pushed a commit
that referenced
this issue
Oct 28, 2020
This ensures that we don't attempt to reconnect to peers that have disconnected from us after we have started closing the p2p pool. This may help prevent scenarios where we unintentionally attempt to reconnect to peers after shutting down xud. > Should be tested against [#1668 (comment)](#1668 (comment)) @raladev re-connection after shutdown is disappeared, but my xud still can not be gracefully terminated, it waits something: ``` 28/10/2020 05:17:43.164 [CONNEXT] trace: sending request to /balance/0x69C3d485623bA3f382Fc0FB6756c4574d43C1618 ^C28/10/2020 05:17:44.087 [GLOBAL] info: XUD is shutting down 28/10/2020 05:17:44.088 [LND-BTC] info: new status: Disconnected 28/10/2020 05:17:44.089 [LND-LTC] info: new status: Disconnected 28/10/2020 05:17:44.090 [CONNEXT] info: new status: Disconnected 28/10/2020 05:17:44.093 [P2P] debug: Peer 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow): closing socket. reason: Shutdown 28/10/2020 05:17:44.095 [HTTP] info: http server has closed 28/10/2020 05:17:44.096 [RPC] info: gRPC server completed shutdown 28/10/2020 05:17:44.097 [P2P] trace: Sent Disconnecting packet to 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow): "{\"body\":{\"reason\":9},\"header\":{\"id\":\"95133be0-1917-11eb-b75b-73d0f0278756\"}}" 28/10/2020 05:17:44.109 [ORDERBOOK] debug: removed all orders for peer 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow) 28/10/2020 05:17:44.118 [GLOBAL] info: XUD shutdown gracefully ```
rsercano
added a commit
that referenced
this issue
Nov 5, 2020
Merged
|
Closed by #1994. |
raladev
added a commit
that referenced
this issue
Nov 19, 2020
* feat: removeorder output changed to a more meaningful message (#1526) * fix(p2p): don't reconnect peers when pool closed (#1965) This ensures that we don't attempt to reconnect to peers that have disconnected from us after we have started closing the p2p pool. This may help prevent scenarios where we unintentionally attempt to reconnect to peers after shutting down xud. > Should be tested against [#1668 (comment)](#1668 (comment)) @raladev re-connection after shutdown is disappeared, but my xud still can not be gracefully terminated, it waits something: ``` 28/10/2020 05:17:43.164 [CONNEXT] trace: sending request to /balance/0x69C3d485623bA3f382Fc0FB6756c4574d43C1618 ^C28/10/2020 05:17:44.087 [GLOBAL] info: XUD is shutting down 28/10/2020 05:17:44.088 [LND-BTC] info: new status: Disconnected 28/10/2020 05:17:44.089 [LND-LTC] info: new status: Disconnected 28/10/2020 05:17:44.090 [CONNEXT] info: new status: Disconnected 28/10/2020 05:17:44.093 [P2P] debug: Peer 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow): closing socket. reason: Shutdown 28/10/2020 05:17:44.095 [HTTP] info: http server has closed 28/10/2020 05:17:44.096 [RPC] info: gRPC server completed shutdown 28/10/2020 05:17:44.097 [P2P] trace: Sent Disconnecting packet to 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow): "{\"body\":{\"reason\":9},\"header\":{\"id\":\"95133be0-1917-11eb-b75b-73d0f0278756\"}}" 28/10/2020 05:17:44.109 [ORDERBOOK] debug: removed all orders for peer 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow) 28/10/2020 05:17:44.118 [GLOBAL] info: XUD shutdown gracefully ``` * feat(lnd): change gRPC client options * fix(connext): not enough balance for closechannel (#1963) This introduces better error handling for Connext when using `closeChannel` to remove funds from a Connext channel and specifying an amount to remove that is greater than the available balance. * feat: reserved capacity checks on PlaceOrder (#1949) This rejects orders that would put our total reserved balance over our total capacity for either the outbound or inbound currency. The sum of the inbound & outbound amounts for a newly placed order are added to the amounts reserved by open orders, and if either of these amounts exceed the corresponding capacity then the request to place the order is rejected. An exception to this are inbound limits for Connext currencies, since we have the ability to dynamically request additional inbound collateral via our "lazy collateral" approach. It is still possible for market orders to cause our open orders to exceed our capacity. This is a difficult problem to avoid entirely, as the price that market orders will execute at is unknown until the execution is complete. Even if we simulate the matching routine, we won't know which matches will succeed until we attempt a swap. Instead, we generously assume that market orders will execute at the best quoted price for purposes of these capacity checks. For users that simultaneously place limit orders and market orders for the same currencies, it should be made clear that market orders may use up their available balance needed for their limit orders to succeed. Closes #1947. * fix(cli): openchannel assertion error for string amount (#1950) Fixes #1643. * feat(swapclient): auto init wallets on xud unlock (#1973) This adds a new feature to xud to automatically attempt to create a wallet for any new swap client configured after an xud node has been created. Effectively this only changes the behavior for lnd clients, as this is already the existing behavior for Connext. The process for initializing has now been standardized instead of the ad hoc approach used previously. If xud tries to unlock an lnd node and gets an error message indicating that the wallet has not been created, then it will generate a client & currency specific seed mnemonic using seedutil and call `InitWallet` with that seed and the existing xud password, such that the wallet funds and node identity for the new lnd client can be unlocked and restored along with the rest of lnd. Closes #1929. * feat(rpc): runtime addcurrency for lnd & connext (#1746) Co-authored-by: Le Premier Homme <interjoint1@gmail.com> * refactor(rpc): rename reserved TradingLimits fields This renames the `reservedOutbound` and `reservedInbound` fields on the `TradingLimits` call to `reservedSell` and `reservedBuy` respectively. * fix(rpc): no success if no channels to close (#1689) (#1942) Co-authored-by: rsercano <ozdemirsercan27@gmail.com> Co-authored-by: Daniel McNally <mcnallydp@gmail.com> * fix: tls certificate check on startup (#1510) * fix: alias missing in streamorders (#1725) (#1962) * fix(lnd): handling hold invoice check errors (#1969) This adds better error handling for when the test calls to verify lnd hold invoices are available fail due to connectivity reasons. Previously any error that occurred at this step would cause us to set lnd's status to `NoHoldInvoiceSupport` including connection issues. There was also a bug that caused us to try to set the status to connected even when a hold invoice status check failed. This could result in the unusual behavior of status going to `Disconnected` upon a call failing due to the grpc `UNAVAILABLE` error status, then being set to `NoHoldInvoiceSupport` and then to `ConnectionVerified`. Now we only set `NoHoldInvoiceSupport` when the test calls fail for a reason other than `UNAVAILABLE`, and we only set the status to `ConnectionVerified` when the hold invoice calls succeed. Closes #1968. * feat(lnd): SendPaymentV2 This migrates the call we use to send payments with lnd from the deprecated `SendPaymentSync` to `SendPaymentV2` which allows for multi path payments, among other improvements. As part of this change, the lnd proto files have been updated to their v0.11.x versions and the version of lnd used in simulation tests has been updated to v0.11.1 as well. Closes #1590. * Revert "feat: removeorder output changed to a more meaningful message (#1526)" * fix: use regtest instead of regnet arg This fixes a bug where the xud flag to set the network was incorrectly configured as `regnet` when it should be `regtest` to match what xud expects. * fix(lnd): don't calculate negative capacities This fixes a bug in the logic for calculating the inbound & outbound amount/capacity totals. We subtract the channel reserve amounts from the balances when determining how large a payment the channel could support, however we should not end up with a negative number. * feat: new grpc call for subscribring alerts such as low balance (#864) * fix: changes removeorder output to a more meaningful message (#1526) (#1986) Co-authored-by: rsercano <ozdemirsercan27@gmail.com> Co-authored-by: Daniel McNally <mcnallydp@gmail.com> Co-authored-by: Karl Ranna <karl@karlranna.com> Co-authored-by: Le Premier Homme <interjoint1@gmail.com>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Xud logs from the start of the application that resulted in memory leaks.
xud-not-able-to-gracefully-shutdown.log
I suspect it's because after swap failure/timeout we're forgetting about cleaning up some listeners.
The text was updated successfully, but these errors were encountered: