xud doesn't shut down gracefully with active rpc streaming calls #699

offerm · 2018-11-21T17:01:39Z

xucli shutdown does not bring the process down and does not close the active peer connections.

sangaman · 2018-11-23T05:59:20Z

Can you provide more details/steps to reproduce? If I start up xud, connect to peers, and then run xucli shutdown it does end the process. Do you see different?

offerm · 2018-11-23T06:02:15Z

Yes. Will try to generate a log

…

On Fri, 23 Nov 2018 at 7:59 Daniel McNally ***@***.***> wrote: Can you provide more details/steps to reproduce? If I start up xud, connect to peers, and then run xucli shutdown it does end the process. Do you see different? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#699 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AJQ0cibYu-a7y0nSAFsF86Y5Sm28CV9Hks5ux464gaJpZM4Ytibn> .

sangaman · 2018-11-23T06:05:12Z

Thanks, I do see at least one thing that could keep us from ending the process (the peer reconnection timers) so that might be the issue here.

offerm · 2018-11-23T06:10:39Z

This is what I find in the log:

11/23/2018, 6:05:52 AM [GLOBAL] info: XUD is shutting down
11/23/2018, 6:05:52 AM [RPC] info: gRPC Web API proxy stopped listening

Easy to reproduce on test1.xud
~

offerm · 2018-11-23T06:18:49Z

You need to have a peer connected to the node to see the problem.

offerm · 2018-11-23T06:19:42Z

Also note that it is not working also with master.

This properly cancels the timer to retry a connection to a peer when the peer is closed. Not canceling the timer could interfere with gracefully shutting down `xud`, as the process would continue waiting for the timer after. Fixes #699.

This properly cancels the timer to retry a connection to a peer when the peer is closed. Not canceling the timer could interfere with gracefully shutting down `xud`, as the process would continue waiting for the timer. Fixes #699.

sangaman · 2018-11-23T06:26:07Z

Can you retry your test with the branch from #701?

offerm · 2018-11-23T06:33:21Z

Not solved. Suggest you start by reproducing the problem.

sangaman · 2018-11-23T06:40:31Z

Ok I'll have to revisit tomorrow. It's not as simple as having a peer connected as my first try to reproduce did not have this issue even with peers connected. Can you share the full log including all peers you connected to? Are you just starting xud and then shutting down, or doing anything else in between?

offerm · 2018-11-29T16:11:01Z

Log file:

11/29/2018, 4:05:53 PM [P2P] verbose: received 10 orders from 03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.86,"quantity":0.003,"isBuy":true,"hold":0,"id":"e16cbf80-f2d0-11e8-9339-79fb57d4a049","initialQuant
ity":0.003,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553591}
11/29/2018, 4:05:53 PM [P2P] verbose: received 0 nodes (0 new) from 03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.87,"quantity":0.0025,"isBuy":true,"hold":0,"id":"e16d34b0-f2d0-11e8-9339-79fb57d4a049","initialQuan
tity":0.0025,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553592}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.88,"quantity":0.002,"isBuy":true,"hold":0,"id":"e16d82d0-f2d0-11e8-9339-79fb57d4a049","initialQuant
ity":0.002,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553593}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.89,"quantity":0.0015,"isBuy":true,"hold":0,"id":"e16dd0f0-f2d0-11e8-9339-79fb57d4a049","initialQuan
tity":0.0015,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553594}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.9,"quantity":0.001,"isBuy":true,"hold":0,"id":"e16df801-f2d0-11e8-9339-79fb57d4a049","initialQuanti
ty":0.001,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553594}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.14,"quantity":0.003,"isBuy":false,"hold":0,"id":"e16bae10-f2d0-11e8-9339-79fb57d4a049","initialQuan
tity":0.003,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553595}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.1,"quantity":0.001,"isBuy":false,"hold":0,"id":"e16e4620-f2d0-11e8-9339-79fb57d4a049","initialQuant
ity":0.001,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553596}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.11,"quantity":0.0015,"isBuy":false,"hold":0,"id":"e16e6d31-f2d0-11e8-9339-79fb57d4a049","initialQua
ntity":0.0015,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553596}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.12,"quantity":0.002,"isBuy":false,"hold":0,"id":"e16ebb50-f2d0-11e8-9339-79fb57d4a049","initialQuan
tity":0.002,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553597}
11/29/2018, 4:05:53 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.13,"quantity":0.0025,"isBuy":false,"hold":0,"id":"e16ee261-f2d0-11e8-9339-79fb57d4a049","initialQua
ntity":0.0025,"peerPubKey":"03fd337659e99e628d0487e4f87acf93e353db06f754dccc402f2de1b857a319d0","createdAt":1543507553597}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.14,"quantity":0.003,"isBuy":false,"localId":"a87cc550-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a
87cc550-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.003,"createdAt":1543507557925}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.86,"quantity":0.003,"isBuy":true,"localId":"a87dd6c0-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a8
7dd6c0-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.003,"createdAt":1543507557932}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.87,"quantity":0.0025,"isBuy":true,"localId":"a87e4bf0-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a
87e4bf0-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.0025,"createdAt":1543507557935}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.88,"quantity":0.002,"isBuy":true,"localId":"a87e9a10-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a8
7e9a10-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.002,"createdAt":1543507557937}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.89,"quantity":0.0015,"isBuy":true,"localId":"a87ee830-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a
87ee830-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.0015,"createdAt":1543507557939}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.9,"quantity":0.001,"isBuy":true,"localId":"a87f3650-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a87
f3650-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.001,"createdAt":1543507557941}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.1,"quantity":0.001,"isBuy":false,"localId":"a87f8470-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a8
7f8470-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.001,"createdAt":1543507557943}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.11,"quantity":0.0015,"isBuy":false,"localId":"a87fab81-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"
a87fab81-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.0015,"createdAt":1543507557944}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.12,"quantity":0.002,"isBuy":false,"localId":"a87ff9a0-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"a
87ff9a0-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.002,"createdAt":1543507557946}
11/29/2018, 4:05:57 PM [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":1.13,"quantity":0.0025,"isBuy":false,"localId":"a88047c0-f3f0-11e8-b91a-1bbeae0a7374","hold":0,"id":"
a88047c0-f3f0-11e8-b91a-1bbeae0a7374","initialQuantity":0.0025,"createdAt":1543507557948}
11/29/2018, 4:06:08 PM [P2P] debug: Connected pre-handshake to peer 199.203.79.137:64348
11/29/2018, 4:06:08 PM [P2P] verbose: received hello packet from 199.203.79.137:64348: {"version":"1.0.0-alpha.4","pairs":["LTC/BTC"],"nodePubKey":"0343d327538650a721fa193aaf8bfb7cc9a2
9a5017a74d0e03a73b74ff1660067d","lndbtcPubKey":"0335e67026ea6aa687f2c7858b40ffac0354c726b30795b86fe958e3f663c77a31","lndltcPubKey":"020944f8cc2e9b96fa86808226e8450ebbf14b2d825477a45d0e
166adfee9931ba","addresses":[]}
11/29/2018, 4:06:08 PM [P2P] verbose: opened connection to 0343d327538650a721fa193aaf8bfb7cc9a29a5017a74d0e03a73b74ff1660067d at 199.203.79.137:64348
11/29/2018, 4:06:09 PM [P2P] verbose: received 0 orders from 0343d327538650a721fa193aaf8bfb7cc9a29a5017a74d0e03a73b74ff1660067d
11/29/2018, 4:06:09 PM [P2P] verbose: received 0 nodes (0 new) from 0343d327538650a721fa193aaf8bfb7cc9a29a5017a74d0e03a73b74ff1660067d
11/29/2018, 4:06:31 PM [GLOBAL] info: XUD is shutting down
11/29/2018, 4:06:31 PM [RPC] info: gRPC Web API proxy stopped listening

offerm · 2018-11-29T16:12:31Z

@sangaman The problem is due to a stream connection which is open to the server.

You can reproduce by the following:

start xud
xucli streamorders &

3. xucli shutdown

The process will not exit until you kill

sangaman · 2018-11-30T07:24:01Z

Thanks for figuring that out! I was stuck since I'd never been calling streamorders - that makes sense. I'll open a PR for a fix.

This tracks all active streaming gRPC calls and closes them when the gRPC server is shut down. Previously, active streaming calls would prevent `xud` from shutting down gracefully. Fixes #699.

offerm · 2018-11-30T08:42:45Z

Will check thebPr later today. Looks like this is not the only reason why shutdown may not work. I face it on a different configuration even without the stream. Will try to understand why and let you know.

…

On Fri, 30 Nov 2018 at 9:24 Daniel McNally ***@***.***> wrote: Thanks for figuring that out! I was stuck since I'd never been calling streamorders - that makes sense. I'll open a PR for a fix. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#699 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AJQ0ct-MNfUo0XXTb8f7W6ehpru_gwpUks5u0N0SgaJpZM4Ytibn> .

offerm · 2018-11-30T10:43:37Z

Yes.
If a node has an incoming connection, shutdown will not work.
@sangaman

This tracks all active streaming gRPC calls and closes them when the gRPC server is shut down. Previously, active streaming calls would prevent `xud` from shutting down gracefully. Fixes #699.

offerm mentioned this issue Nov 22, 2018

feat(p2p): reconnect to peer after disconnection #695

Merged

sangaman added the bug Something isn't working label Nov 23, 2018

sangaman mentioned this issue Nov 23, 2018

fix(p2p): cancel retry connection timer #701

Merged

ghost assigned sangaman Nov 23, 2018

ghost added the in progress label Nov 23, 2018

kilrau added this to the 1.0.0-alpha.6 milestone Nov 26, 2018

kilrau changed the title ~~xucli shutdown~~ xucli 'shutdown' doesn't shut down xud process Nov 26, 2018

sangaman mentioned this issue Nov 30, 2018

fix(rpc): close streaming calls on shutdown #717

Merged

sangaman closed this as completed in #717 Dec 2, 2018

ghost removed the in progress label Dec 2, 2018

sangaman mentioned this issue Dec 2, 2018

Inbound peers block shutdown process #719

Closed

sangaman changed the title ~~xucli 'shutdown' doesn't shut down xud process~~ xud doesn't shut down gracefully with active rpc streaming calls Dec 2, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

xud doesn't shut down gracefully with active rpc streaming calls #699

xud doesn't shut down gracefully with active rpc streaming calls #699

offerm commented Nov 21, 2018

sangaman commented Nov 23, 2018

offerm commented Nov 23, 2018 via email

sangaman commented Nov 23, 2018

offerm commented Nov 23, 2018

offerm commented Nov 23, 2018

offerm commented Nov 23, 2018

sangaman commented Nov 23, 2018

offerm commented Nov 23, 2018

sangaman commented Nov 23, 2018

offerm commented Nov 29, 2018

offerm commented Nov 29, 2018

sangaman commented Nov 30, 2018

offerm commented Nov 30, 2018 via email

offerm commented Nov 30, 2018

xud doesn't shut down gracefully with active rpc streaming calls #699

xud doesn't shut down gracefully with active rpc streaming calls #699

Comments

offerm commented Nov 21, 2018

sangaman commented Nov 23, 2018

offerm commented Nov 23, 2018 via email

sangaman commented Nov 23, 2018

offerm commented Nov 23, 2018

offerm commented Nov 23, 2018

offerm commented Nov 23, 2018

sangaman commented Nov 23, 2018

offerm commented Nov 23, 2018

sangaman commented Nov 23, 2018

offerm commented Nov 29, 2018

offerm commented Nov 29, 2018

sangaman commented Nov 30, 2018

offerm commented Nov 30, 2018 via email

offerm commented Nov 30, 2018