Shutdown is too slow

[ligi]

follow up from #21917
either make it faster or make it more resilient when shutting down to not lead to bad states

[bokkypoobah]

Experiencing issues with the geth shutdown as well.

Dec 04 07:11:55 zozzfozzel geth[764]: INFO [12-04|07:11:55.458] Got interrupt, shutting down...
Dec 04 07:11:55 zozzfozzel geth[764]: INFO [12-04|07:11:55.958] HTTP server stopped                      endpoint=127.0.0.1:8545
Dec 04 07:11:55 zozzfozzel geth[764]: INFO [12-04|07:11:55.960] IPC endpoint closed                      url=/home/geth/.ethereum/geth.ipc
Dec 04 07:11:55 zozzfozzel geth[764]: INFO [12-04|07:11:55.960] Terminated topic registration            topic=LES2@d4e56740f876aef8
Dec 04 07:12:10 zozzfozzel geth[764]: INFO [12-04|07:12:10.989] Deep froze chain segment                 blocks=4    elapsed=12.895ms  number=11291759 hash="8e1db4…ae4e57"
Dec 04 07:12:22 zozzfozzel geth[764]: WARN [12-04|07:12:22.883] Checkpoint challenge timed out, dropping id=6a0f99574c10145e conn=dyndial addr=150.109.126.69:30303  type=Geth/v1.9.24-stable-...
Dec 04 07:12:40 zozzfozzel geth[764]: INFO [12-04|07:12:40.282] Imported new chain segment               blocks=1    txs=205   mgas=12.478  elapsed=160.840ms mgasps=77.582  number=11381760 hash="bf9a98…91a623" age=1m1s      dirty=1022.46MiB
Dec 04 07:13:12 zozzfozzel geth[764]: INFO [12-04|07:13:12.576] Imported new chain segment               blocks=1    txs=389   mgas=12.455  elapsed=123.502ms mgasps=100.849 number=11381761 hash="4276af…a995f1" dirty=1022.51MiB
Dec 04 07:14:11 zozzfozzel geth[764]: INFO [12-04|07:14:11.002] Deep froze chain segment                 blocks=2    elapsed=12.018ms  number=11291761 hash="975c1f…69f1b1"
Dec 04 07:14:37 zozzfozzel geth[764]: INFO [12-04|07:14:37.151] Imported new chain segment               blocks=1    txs=202   mgas=12.488  elapsed=129.809ms mgasps=96.199  number=11381762 hash="8565c4…7aaa46" age=1m26s     dirty=1022.74MiB
Dec 04 07:14:47 zozzfozzel geth[764]: INFO [12-04|07:14:47.451] Imported new chain segment               blocks=1    txs=191   mgas=12.464  elapsed=123.413ms mgasps=100.993 number=11381763 hash="e77f2a…489380" dirty=1022.46MiB
Dec 04 07:14:49 zozzfozzel geth[764]: INFO [12-04|07:14:49.888] Imported new chain segment               blocks=1    txs=188   mgas=12.482  elapsed=457.867ms mgasps=27.262  number=11381764 hash="b3cb61…db5237" dirty=1022.77MiB
Dec 04 07:14:51 zozzfozzel geth[764]: INFO [12-04|07:14:51.863] Imported new chain segment               blocks=1    txs=147   mgas=12.461  elapsed=1.156s    mgasps=10.777  number=11381765 hash="6365ff…174761" dirty=1022.59MiB
Dec 04 07:14:51 zozzfozzel geth[764]: INFO [12-04|07:14:51.944] Imported new chain segment               blocks=1    txs=149   mgas=12.485  elapsed=81.334ms  mgasps=153.503 number=11381765 hash="38cb8b…430a2f" dirty=1022.75MiB
Dec 04 07:14:52 zozzfozzel geth[764]: INFO [12-04|07:14:52.496] Chain reorg detected                     number=11381764 hash="b3cb61…db5237" drop=1 dropfrom="6365ff…174761" add=2 addfrom="9c3614…cc253c"
Dec 04 07:14:52 zozzfozzel geth[764]: INFO [12-04|07:14:52.500] Imported new chain segment               blocks=1    txs=172   mgas=12.508  elapsed=108.364ms mgasps=115.427 number=11381766 hash="9c3614…cc253c" dirty=1022.53MiB
Dec 04 07:15:03 zozzfozzel geth[764]: WARN [12-04|07:15:03.485] Already shutting down, interrupt more to panic. times=9
Dec 04 07:15:03 zozzfozzel geth[764]: INFO [12-04|07:15:03.672] Imported new chain segment               blocks=1    txs=123   mgas=12.510  elapsed=133.953ms mgasps=93.393  number=11381767 hash="ad74f5…6ea36f" dirty=1023.18MiB
Dec 04 07:15:09 zozzfozzel geth[764]: INFO [12-04|07:15:09.285] Imported new chain segment               blocks=1    txs=184   mgas=12.503  elapsed=141.811ms mgasps=88.170  number=11381768 hash="fb2038…c93b0a" dirty=1022.52MiB
Dec 04 07:15:11 zozzfozzel geth[764]: INFO [12-04|07:15:11.015] Deep froze chain segment                 blocks=7    elapsed=12.485ms  number=11291768 hash="a7b4bc…e4a15a"
Dec 04 07:15:14 zozzfozzel geth[764]: INFO [12-04|07:15:14.788] Imported new chain segment               blocks=1    txs=166   mgas=12.512  elapsed=128.842ms mgasps=97.110  number=11381769 hash="4a2da4…06a874" dirty=1022.29MiB
Dec 04 07:15:18 zozzfozzel geth[764]: INFO [12-04|07:15:18.062] Imported new chain segment               blocks=1    txs=139   mgas=12.489  elapsed=90.776ms  mgasps=137.576 number=11381770 hash="d21588…908ed1" dirty=1023.10MiB
Dec 04 07:15:44 zozzfozzel geth[764]: INFO [12-04|07:15:44.272] Imported new chain segment               blocks=1    txs=196   mgas=12.474  elapsed=189.911ms mgasps=65.682  number=11381771 hash="858e8c…2349f2" dirty=1022.76MiB
Dec 04 07:15:48 zozzfozzel geth[764]: INFO [12-04|07:15:48.151] Imported new chain segment               blocks=1    txs=142   mgas=12.462  elapsed=103.671ms mgasps=120.207 number=11381772 hash="d3ca88…c3004d" dirty=1022.31MiB
Dec 04 07:15:57 zozzfozzel geth[764]: INFO [12-04|07:15:57.998] Imported new chain segment               blocks=1    txs=137   mgas=12.450  elapsed=172.826ms mgasps=72.037  number=11381773 hash="9b5946…f7b923" dirty=1022.72MiB
Dec 04 07:16:05 zozzfozzel geth[764]: INFO [12-04|07:16:05.485] Imported new chain segment               blocks=1    txs=163   mgas=12.269  elapsed=132.791ms mgasps=92.391  number=11381774 hash="0770aa…cb2415" dirty=1022.56MiB
Dec 04 07:16:06 zozzfozzel geth[764]: INFO [12-04|07:16:06.399] Imported new chain segment               blocks=1    txs=0     mgas=0.000   elapsed=16.408ms  mgasps=0.000   number=11381775 hash="1f9e58…33c415" dirty=1021.06MiB
Dec 04 07:16:11 zozzfozzel geth[764]: INFO [12-04|07:16:11.035] Deep froze chain segment                 blocks=7    elapsed=16.237ms  number=11291775 hash="ca7604…7f385b"
Dec 04 07:16:12 zozzfozzel geth[764]: INFO [12-04|07:16:12.501] Imported new chain segment               blocks=1    txs=136   mgas=12.441  elapsed=113.503ms mgasps=109.607 number=11381776 hash="3c4745…8177da" dirty=1021.15MiB
Dec 04 07:16:13 zozzfozzel geth[764]: INFO [12-04|07:16:13.282] Imported new chain segment               blocks=1    txs=144   mgas=12.312  elapsed=92.223ms  mgasps=133.503 number=11381777 hash="dd7e70…5ffdcd" dirty=1021.00MiB
Dec 04 07:16:18 zozzfozzel geth[764]: INFO [12-04|07:16:18.595] Imported new chain segment               blocks=1    txs=193   mgas=12.445  elapsed=97.510ms  mgasps=127.626 number=11381778 hash="a38327…666837" dirty=1021.22MiB
Dec 04 07:16:32 zozzfozzel geth[764]: INFO [12-04|07:16:32.519] Imported new chain segment               blocks=1    txs=168   mgas=12.427  elapsed=151.894ms mgasps=81.814  number=11381779 hash="993f85…efe74c" dirty=1021.22MiB
Dec 04 07:16:36 zozzfozzel geth[764]: INFO [12-04|07:16:36.066] Imported new chain segment               blocks=1    txs=109   mgas=12.446  elapsed=110.722ms mgasps=112.407 number=11381780 hash="b60a19…0fbbcd" dirty=1022.00MiB
Dec 04 07:16:50 zozzfozzel geth[764]: INFO [12-04|07:16:50.962] Imported new chain segment               blocks=1    txs=154   mgas=12.426  elapsed=291.779ms mgasps=42.588  number=11381781 hash="800df7…03dda4" dirty=1022.48MiB
Dec 04 07:16:55 zozzfozzel systemd[1]: geth.service: State 'stop-sigterm' timed out. Killing.
Dec 04 07:16:55 zozzfozzel systemd[1]: geth.service: Killing process 764 (geth) with signal SIGKILL.
Dec 04 07:16:55 zozzfozzel systemd[1]: geth.service: Main process exited, code=killed, status=9/KILL
Dec 04 07:16:55 zozzfozzel systemd[1]: geth.service: Failed with result 'timeout'.
Dec 04 07:16:55 zozzfozzel systemd[1]: Stopped Geth.
Dec 04 07:17:34 zozzfozzel systemd[1]: Started Geth.

Sent geth a systemd restart. geth receives the interrupt and says it's shutting down. But geth continues receiving new blocks. systemd then sends a KILL signal - default is 90 seconds but I've configured to 3 minutes. You can see the KILL signal logged.

geth then loses about 30,000+ blocks, and has to resync again.

[holiman]

@bokkypoobah were you running light server? We recently fixed a shutdown-hang there: #21927

[bokkypoobah]

@bokkypoobah were you running light server? We recently fixed a shutdown-hang there: #21927

Yes. Had --light.serve 20 . Removed this parameter before the last restart, so hopefully this problem will no longer happen.

[ligi]

duplicate of #22524