Strange shutdown/restart behavior on 0.22.2

[yaneony]

Bug description

After upgrading to 0.22.2 restart or shutdown take like over 10 minutes on latest Debian. Installed from *.deb. Working like a charm on 0.22.1.

Environment

• OS: Debian

• Headscale version: 0.22.2

• Tailscale version: 1.40.1 (not relevant)

• Headscale is behind a (reverse) proxy

• Headscale runs in a container

To Reproduce

Upgrade, do systemd restart headscale, wait like for 10 minutes to restart.

[iamid0]

I have got a similar issue. This is a fresh install of Debian, and headscale is installed via *deb file.

root@ip-172-26-2-175:/etc/headscale# cat /etc/debian_version
11.7
root@ip-172-26-2-175:/etc/headscale# headscale  version
v0.22.3
root@ip-172-26-2-175:/etc/headscale# time systemctl restart headscale

real	1m30.078s
user	0m0.007s
sys	0m0.000s
root@ip-172-26-2-175:/etc/headscale#

At the same time, I read the following message by running tail -f syslog | grep headscale

Jun  5 10:14:27 ip-172-26-2-175 headscale[13726]: 2023-06-05T10:14:27+08:00 ERR error getting routes error="sql: database is closed"
Jun  5 10:14:27 ip-172-26-2-175 headscale[13726]: 2023-06-05T10:14:27+08:00 ERR Error listing users error="sql: database is closed"
Jun  5 10:14:27 ip-172-26-2-175 headscale[13726]: 2023-06-05T10:14:27+08:00 ERR Error listing users error="sql: database is closed"
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: State 'stop-sigterm' timed out. Killing.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13726 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13727 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13728 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13729 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13730 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13731 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Killing process 13732 (headscale) with signal SIGKILL.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Main process exited, code=killed, status=9/KILL
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Failed with result 'timeout'.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: Stopped headscale controller.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: headscale.service: Consumed 1.076s CPU time.
Jun  5 10:14:29 ip-172-26-2-175 systemd[1]: Started headscale controller.

[lionslair]

I am getting the same on ubuntu 22.04

eventually restarts though

[KamilBaczkowski]

I am also affected by this issue, I checked systemd logs and I found this:

Jun 13 15:45:45 grzybnia systemd[1]: Stopping headscale controller...
Jun 13 15:45:45 grzybnia headscale[9837]: 2023-06-13T15:45:45-04:00 INF Received signal to stop, shutting down gracefully signal=terminated
Jun 13 15:45:45 grzybnia headscale[9837]: 2023-06-13T15:45:45-04:00 INF The long-poll handler is shutting down handler=PollNetMapStream machine=kavelachowo noise=true
Jun 13 15:45:45 grzybnia headscale[9837]: 2023-06-13T15:45:45-04:00 INF The long-poll handler is shutting down handler=PollNetMapStream machine=gender noise=false
Jun 13 15:45:45 grzybnia headscale[9837]: 2023-06-13T15:45:45-04:00 INF Headscale stopped
Jun 13 15:45:46 grzybnia headscale[9837]: 2023-06-13T15:45:46-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:45:46 grzybnia headscale[9837]: 2023-06-13T15:45:46-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:45:51 grzybnia headscale[9837]: 2023-06-13T15:45:51-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:45:51 grzybnia headscale[9837]: 2023-06-13T15:45:51-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:45:56 grzybnia headscale[9837]: 2023-06-13T15:45:56-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:45:56 grzybnia headscale[9837]: 2023-06-13T15:45:56-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:45:56 grzybnia headscale[9837]: 2023-06-13T15:45:56-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:45:57 grzybnia headscale[9837]: 2023-06-13T15:45:57-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:46:01 grzybnia headscale[9837]: 2023-06-13T15:46:01-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:01 grzybnia headscale[9837]: 2023-06-13T15:46:01-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:06 grzybnia headscale[9837]: 2023-06-13T15:46:06-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:06 grzybnia headscale[9837]: 2023-06-13T15:46:06-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:10 grzybnia headscale[9837]: 2023-06-13T15:46:10-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:46:11 grzybnia headscale[9837]: 2023-06-13T15:46:11-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:11 grzybnia headscale[9837]: 2023-06-13T15:46:11-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:11 grzybnia headscale[9837]: 2023-06-13T15:46:11-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:16 grzybnia headscale[9837]: 2023-06-13T15:46:16-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:16 grzybnia headscale[9837]: 2023-06-13T15:46:16-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:17 grzybnia headscale[9837]: 2023-06-13T15:46:17-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:46:21 grzybnia headscale[9837]: 2023-06-13T15:46:21-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:21 grzybnia headscale[9837]: 2023-06-13T15:46:21-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:21 grzybnia headscale[9837]: 2023-06-13T15:46:21-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:26 grzybnia headscale[9837]: 2023-06-13T15:46:26-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:26 grzybnia headscale[9837]: 2023-06-13T15:46:26-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:30 grzybnia headscale[9837]: 2023-06-13T15:46:30-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:46:31 grzybnia headscale[9837]: 2023-06-13T15:46:31-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:31 grzybnia headscale[9837]: 2023-06-13T15:46:31-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:36 grzybnia headscale[9837]: 2023-06-13T15:46:36-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:36 grzybnia headscale[9837]: 2023-06-13T15:46:36-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:38 grzybnia headscale[9837]: 2023-06-13T15:46:38-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:46:41 grzybnia headscale[9837]: 2023-06-13T15:46:41-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:41 grzybnia headscale[9837]: 2023-06-13T15:46:41-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:46 grzybnia headscale[9837]: 2023-06-13T15:46:46-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:46 grzybnia headscale[9837]: 2023-06-13T15:46:46-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:46 grzybnia headscale[9837]: 2023-06-13T15:46:46-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:51 grzybnia headscale[9837]: 2023-06-13T15:46:51-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:46:51 grzybnia headscale[9837]: 2023-06-13T15:46:51-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:51 grzybnia headscale[9837]: 2023-06-13T15:46:51-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:56 grzybnia headscale[9837]: 2023-06-13T15:46:56-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:46:56 grzybnia headscale[9837]: 2023-06-13T15:46:56-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:46:56 grzybnia headscale[9837]: 2023-06-13T15:46:56-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:47:01 grzybnia headscale[9837]: 2023-06-13T15:47:01-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:47:01 grzybnia headscale[9837]: 2023-06-13T15:47:01-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:47:01 grzybnia headscale[9837]: 2023-06-13T15:47:01-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:47:06 grzybnia headscale[9837]: 2023-06-13T15:47:06-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:47:06 grzybnia headscale[9837]: 2023-06-13T15:47:06-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:47:08 grzybnia headscale[9837]: 2023-06-13T15:47:08-04:00 ERR Failed to fetch machine from the database with node key: nodekey:redacted handler=NoisePollNetMap
Jun 13 15:47:11 grzybnia headscale[9837]: 2023-06-13T15:47:11-04:00 ERR error getting routes error="sql: database is closed"
Jun 13 15:47:11 grzybnia headscale[9837]: 2023-06-13T15:47:11-04:00 ERR Error listing users error="sql: database is closed"
Jun 13 15:47:16 grzybnia systemd[1]: headscale.service: State 'stop-sigterm' timed out. Killing.

[ptwales]

Seeing the same "database is closed" messages on Arch with versions 0.21.0 and 0.22.3

[paulv]

I am also having this problem on debian 10.13. I did a git bisect and it said the first bad commit was 56dd734. I don't know go so unfortunately I can't help any more than that.

[ptwales]

I'd say the removal of sys.Exit(0) in app.go is the primary suspect. But there's probably a reason why that was removed. Maybe go skips deferred methods if you force exit.

[kradalby]

Yes, the exit broke the defers, I think the fix proposed by @armooo in #1480 should work, I'll try to get that in as part of the refactoring.

[kradalby]

Mentioned fix will be picked up in #1492.