starred/headscale
1
0
Fork 0
mirror of https://github.com/juanfont/headscale.git synced 2026-01-12 04:10:32 +01:00
Code Issues 98 Packages Projects Releases 10 Wiki Activity

[Bug] Nodes fail to remove from notifier - ERR update not sent #830

New Issue
Closed
opened 2025-12-29 02:24:35 +01:00 by adam · 8 comments
adam commented 2025-12-29 02:24:35 +01:00
Owner
Copy Link

Originally created by @dustinblackman on GitHub (Oct 11, 2024).

Is this a support request?

  • This is not a support request

Is there an existing issue for this?

  • I have searched the existing issues

Current Behavior

There is a two part bug related to node notification updates. When a node either loses connection/system goes to sleep, this logic expects that Notifier.RemoveNode will be called before the next sendAll loop, where the effected node won't be there anymore.

I have systems coming in and out of my network during the day, and when some go offline they're not correctly removed from the notifier, resulting in the notifier.sendAll function emitting the following logs until a disconnect event is finally emitted, or Headscale is rebooted.

2024-10-11T13:14:50Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:15:15Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:15:20Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:15:39Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:15:44Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:15:49Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:15:59Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66
2024-10-11T13:16:04Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:16:15Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:16:24Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:16:31Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:16:32Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:16:40Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:16:52Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:17:12Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:17:14Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:17:27Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:17:32Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:17:35Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:18:08Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:31:12Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:31:15Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:31:17Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:31:32Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:31:34Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66  
2024-10-11T13:31:37Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66

With the first problem of Notifier.RemoveNode not being called when a node goes offline in all instances, secondly this issue occurs where logic in sendAll will not work as intended, as any node in the n.nodes array after the failed node will not receive updates.

I have yet to pin point why the first issue occurs. I have a feeling the desktop Tailscale clients are not correctly calling disconnect when a machine goes to sleep, but eventually do at same point as the errors above stop after awhile when updating the sendAll functions to continue looping through nodes rather than returning early.

Expected Behavior

  1. When a node goes offline, it is correctly removed from the notifiers available nodes list.
  2. Even if a node is unreachable, the remaining nodes should continue to receive updates.

Steps To Reproduce

Reproducing I've personally found tricky. I'm deployed using the deb installation package + systemd and will have anywhere between 20 and 40 nodes on the network at a given time. Not all sleep events on machines or ephemeral nodes being removed cause the error to occur.

Environment

- OS: Debian Bookworm
- Headscale version: 0.23.0
- Tailscale version: 1.74.0

Runtime environment

  • Headscale is behind a (reverse) proxy
  • Headscale runs in a container

Anything else?

No response

Originally created by @dustinblackman on GitHub (Oct 11, 2024). ### Is this a support request? - [X] This is not a support request ### Is there an existing issue for this? - [X] I have searched the existing issues ### Current Behavior There is a two part bug related to node notification updates. When a node either loses connection/system goes to sleep, [this logic](https://github.com/juanfont/headscale/blob/60b94b04675b41438ab679f3f2f4b0a0310179a4/hscontrol/notifier/notifier.go#L241-L262) expects that `Notifier.RemoveNode` will be called before the next sendAll loop, where the effected node won't be there anymore. I have systems coming in and out of my network during the day, and when some go offline they're not correctly removed from the notifier, resulting in the `notifier.sendAll` function emitting the following logs until a disconnect event is finally emitted, or Headscale is rebooted. ``` 2024-10-11T13:14:50Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:15:15Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:15:20Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:15:39Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:15:44Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:15:49Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:15:59Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:04Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:15Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:24Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:31Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:32Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:40Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:16:52Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:17:12Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:17:14Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:17:27Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:17:32Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:17:35Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:18:08Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:31:12Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:31:15Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:31:17Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:31:32Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:31:34Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 2024-10-11T13:31:37Z ERR update not sent, context cancelled error="context deadline exceeded" node.id=66 ``` With the first problem of `Notifier.RemoveNode` not being called when a node goes offline in all instances, secondly this issue occurs where [logic in `sendAll`](https://github.com/juanfont/headscale/blob/60b94b04675b41438ab679f3f2f4b0a0310179a4/hscontrol/notifier/notifier.go#L262) will not work as intended, as any node in the `n.nodes` array after the failed node will not receive updates. I have yet to pin point why the first issue occurs. I have a feeling the desktop Tailscale clients are not correctly calling `disconnect` when a machine goes to sleep, but _eventually_ do at same point as the errors above stop after awhile when updating the sendAll functions to `continue` looping through nodes rather than returning early. ### Expected Behavior 1. When a node goes offline, it is correctly removed from the notifiers available nodes list. 2. Even if a node is unreachable, the remaining nodes should continue to receive updates. ### Steps To Reproduce Reproducing I've personally found tricky. I'm deployed using the deb installation package + systemd and will have anywhere between 20 and 40 nodes on the network at a given time. Not all sleep events on machines or ephemeral nodes being removed cause the error to occur. ### Environment ```markdown - OS: Debian Bookworm - Headscale version: 0.23.0 - Tailscale version: 1.74.0 ``` ### Runtime environment - [ ] Headscale is behind a (reverse) proxy - [ ] Headscale runs in a container ### Anything else? _No response_
adam added the bugno-stale-bot labels 2025-12-29 02:24:35 +01:00
adam closed this issue 2025-12-29 02:24:36 +01:00
adam commented 2025-12-29 02:24:36 +01:00
Author
Owner
Copy Link

@photoszzt commented on GitHub (May 28, 2025):

@kradalby If we remove the return, is this problem solved?

@photoszzt commented on GitHub (May 28, 2025): @kradalby If we remove the [return](https://github.com/juanfont/headscale/blob/60b94b04675b41438ab679f3f2f4b0a0310179a4/hscontrol/notifier/notifier.go#L262), is this problem solved?
adam commented 2025-12-29 02:24:36 +01:00
Author
Owner
Copy Link

@fengwk commented on GitHub (Jul 8, 2025):

I encountered the same problem, here is my log
serve.log

@fengwk commented on GitHub (Jul 8, 2025): I encountered the same problem, here is my log [serve.log](https://api.filedoge.com/download/2cac8a5ef151dd711c6b2707aca5496a2651edcd5ce8c7c499a75beecbd06b5993f38daa0143b7a3969f)
adam commented 2025-12-29 02:24:37 +01:00
Author
Owner
Copy Link

@andreyrd commented on GitHub (Jul 11, 2025):

Seeing this as well, I have to restart Headscale every few days when this is triggered to get my network working again.

@andreyrd commented on GitHub (Jul 11, 2025): Seeing this as well, I have to restart Headscale every few days when this is triggered to get my network working again.
adam commented 2025-12-29 02:24:37 +01:00
Author
Owner
Copy Link

@andreyrd commented on GitHub (Jul 21, 2025):

FWIW as a temporary fix I set up a script (inspired by a Tailscale bug several of us did the same for) that just watches headscale logs and restarts it if it detects this (or the panic bug mentioned which seems to lead to this state anyway).

This is for headscale running in a podman container, and is designed to be run by a systemd user unit, but here it is as an example:

#!/bin/bash

logger -t headscale-monitor -p user.info "Monitoring headscale logs..."

while true; do

    # Follow logs for headscale, ignoring any old lines
    podman logs --follow --tail 0 headscale 2>&1 | while read line; do

        if echo "$line" | grep -q 'update not sent, context cancelled error="context deadline exceeded"'; then

            logger -t headscale-monitor -p user.info "$line"
            logger -t headscale-monitor -p user.warning "Context cancelled bug detected. Restarting..."

            podman restart headscale

            # Give it a chance to restart
            sleep 10

            # break out of inner loop to discard any additional logs and start listening fresh
            break
        
        elif echo "$line" | grep -q "invalid memory address or nil pointer dereference"; then

            logger -t headscale-monitor -p user.info "$line"
            logger -t headscale-monitor -p user.warning "Invalid memory address bug detected. Restarting..."

            podman restart headscale

            # Give it a chance to restart
            sleep 10
            
            # break out of inner loop to discard any additional logs and start listening fresh
            break
        
        fi
    done
done
@andreyrd commented on GitHub (Jul 21, 2025): FWIW as a temporary fix I set up a script (inspired by a Tailscale bug several of us did the same for) that just watches headscale logs and restarts it if it detects this (or the panic bug mentioned which seems to lead to this state anyway). This is for headscale running in a podman container, and is designed to be run by a systemd user unit, but here it is as an example: ```bash #!/bin/bash logger -t headscale-monitor -p user.info "Monitoring headscale logs..." while true; do # Follow logs for headscale, ignoring any old lines podman logs --follow --tail 0 headscale 2>&1 | while read line; do if echo "$line" | grep -q 'update not sent, context cancelled error="context deadline exceeded"'; then logger -t headscale-monitor -p user.info "$line" logger -t headscale-monitor -p user.warning "Context cancelled bug detected. Restarting..." podman restart headscale # Give it a chance to restart sleep 10 # break out of inner loop to discard any additional logs and start listening fresh break elif echo "$line" | grep -q "invalid memory address or nil pointer dereference"; then logger -t headscale-monitor -p user.info "$line" logger -t headscale-monitor -p user.warning "Invalid memory address bug detected. Restarting..." podman restart headscale # Give it a chance to restart sleep 10 # break out of inner loop to discard any additional logs and start listening fresh break fi done done ```
adam commented 2025-12-29 02:24:37 +01:00
Author
Owner
Copy Link

@kradalby commented on GitHub (Sep 9, 2025):

As part of solving an update issue with tags and some longstanding architecture issues, this part has been changed so we should no longer drop updates on the floor in this case.

This is part of the work in #2670, particularly b6d5788231 and is now in main. If you have the ability to test it that would be greatly appreciated. Either through main, or alpha/beta that we hopefully can release when we close up more of the milestone issues.

@kradalby commented on GitHub (Sep 9, 2025): As part of solving an update issue with tags and some longstanding architecture issues, this part has been changed so we should no longer drop updates on the floor in this case. This is part of the work in #2670, particularly https://github.com/juanfont/headscale/commit/b6d5788231c865e3d7dfa81008349a0142fdde9d and is now in `main`. If you have the ability to test it that would be greatly appreciated. Either through `main`, or alpha/beta that we hopefully can release when we close up more of the milestone issues.
adam commented 2025-12-29 02:24:37 +01:00
Author
Owner
Copy Link

@kradalby commented on GitHub (Sep 10, 2025):

@dustinblackman I'll close this as the architecture has changed so much from the next release that the error by itself isnt going to be the same. Lets try that out and open a new issue if we see problems still.

@kradalby commented on GitHub (Sep 10, 2025): @dustinblackman I'll close this as the architecture has changed so much from the next release that the error by itself isnt going to be the same. Lets try that out and open a new issue if we see problems still.
adam commented 2025-12-29 02:24:37 +01:00
Author
Owner
Copy Link

@dustinblackman commented on GitHub (Sep 10, 2025):

This sounds great, thank you very much! I'll spin it up in a test cluster this weekend.

@dustinblackman commented on GitHub (Sep 10, 2025): This sounds great, thank you very much! I'll spin it up in a test cluster this weekend.
adam commented 2025-12-29 02:24:37 +01:00
Author
Owner
Copy Link

@matanbaruch commented on GitHub (Sep 30, 2025):

Getting this issue also. Is there any plan for release?

@matanbaruch commented on GitHub (Sep 30, 2025): Getting this issue also. Is there any plan for release?
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
CLI
DERP
DNS
Nix
OIDC
SSH
bug
database
documentation
duplicate
enhancement
faq
good first issue
grants
help wanted
might-come
needs design doc
needs investigation
no-stale-bot
out of scope
performance
policy 📝
pull-request
Mirrored from GitHub Pull Request
 question
regression
routes
stale
tags
tailscale-feature-gap
well described ❤️
wontfix
No Label bug no-stale-bot
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
adam
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: starred/headscale#830
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?