[Bug] macOS unable to connect, node has an open stream(..), rejecting new stream

[casdr]

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

I'm currently experiencing issues with macOS nodes that when switching networks (for example from wired to wireless) or coming back out of sleep, the client is unable to connect to Headscale. Restarting the client doesn't help.

The log is showing the following:

{"level":"info","caller":"/home/runner/work/headscale/headscale/hscontrol/poll.go:657","readOnly":false,"omitPeers":false,"stream":true,"node.id":51,"node":"*redacted*","time":1715779163,"message":"node has an open stream(0xc002214180), rejecting new stream"}
{"level":"info","caller":"/home/runner/work/headscale/headscale/hscontrol/poll.go:657","readOnly":false,"omitPeers":false,"stream":true,"node.id":51,"node":"*redacted*","time":1715779163,"message":"node has an open stream(0xc001db0780), rejecting new stream"}
{"level":"info","caller":"/home/runner/work/headscale/headscale/hscontrol/poll.go:657","readOnly":false,"omitPeers":false,"stream":true,"node.id":51,"node":"*redacted*","time":1715779164,"message":"node has an open stream(0xc002214180), rejecting new stream"}

Restarting Headscale helps. I guess this clears all the current sessions known by Headscale.

Expected Behavior

The client should reconnect succesfully.

Steps To Reproduce

1. Make sure Tailscale is connected
2. Let the device go to sleep and wait a few seconds
3. Turn on the device again
4. Tailscale will have issues reconnecting

Environment

- OS: Debian 11
- Headscale version: v0.23.0-alpha11
- Tailscale version: 1.64.0
- Nginx version: 1.24.0
- Using the reverse proxy from the example for nginx

Runtime environment

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

Anything else?

No response

[casdr]

This is a log of a node that is affected. I'm not sure if this is related to Headscale or the Tailscale client though.

(3.11) mac: ~ % tailscale debug daemon-logs
[logtap connected]
tlsdial: warning: server cert for "hs.<domain>" is not a Let's Encrypt cert
external route: up
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=false nks=false
control: sockstats: trace "ControlClientAuto" was overwritten by another
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
control: doLogin(regen=false, hasUrl=true)
Received auth URL: https://hs.<domain>...
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
monitor: [unexpected] network state changed, but stringification didn't: interfaces.State{defaultRoute=en0 ifs={en0:[192.168.178.20/24 fd1a:a7fd:a1cc:c24b:185e:b60:6e1c:164f/64 llu6]} v4=true v6=true}
monitor: [unexpected] old: {"InterfaceIPs":{"anpi0":null,"anpi1":null,"anpi2":null,"ap1":["fe80::7ce9:1eff:feb1:3a9d/64"],"awdl0":["fe80::1023:71ff:fe81:f103/64"],"bridge0":null,"en0":["192.168.178.20/24","fd1a:a7fd:a1cc:c24b:185e:b60:6e1c:164f/64","fe80::1870:9300:3ebd:c9cf/64"],"en1":null,"en2":null,"en3":null,"en4":null,"en5":null,"en6":null,"gif0":null,"llw0":["fe80::1023:71ff:fe81:f103/64"],"lo0":["127.0.0.1/8","::1/128","fe80::1/64"],"stf0":null,"utun0":["fe80::d80f:4c5e:18ef:6e26/64"],"utun1":["fe80::f171:5d23:c04f:b113/64"],"utun2":["fe80::6a0c:bc60:9cd1:4e48/64"],"utun3":["fe80::ce81:b1c:bd2c:69e/64"],"utun4":null},"Interface":{"anpi0":{"Index":6,"MTU":1500,"Name":"anpi0","HardwareAddr":"7pFxPWiC","Flags":51,"AltAddrs":null,"Desc":""},"anpi1":{"Index":4,"MTU":1500,"Name":"anpi1","HardwareAddr":"7pFxPWiD","Flags":51,"AltAddrs":null,"Desc":""},"anpi2":{"Index":5,"MTU":1500,"Name":"anpi2","HardwareAddr":"7pFxPWiE","Flags":51,"AltAddrs":null,"Desc":""},"ap1":{"Index":14,"MTU":1500,"Name":"ap1","HardwareAddr":"fukesTqd","Flags":51,"AltAddrs":null,"Desc":""},"awdl0":{"Index":16,"MTU":1500,"Name":"awdl0","HardwareAddr":"EiNxgfED","Flags":51,"AltAddrs":null,"Desc":""},"bridge0":{"Index":13,"MTU":1500,"Name":"bridge0","HardwareAddr":"NshwKFsA","Flags":51,"AltAddrs":null,"Desc":""},"en0":{"Index":15,"MTU":1500,"Name":"en0","HardwareAddr":"XOkesTqd","Flags":51,"AltAddrs":null,"Desc":""},"en1":{"Index":10,"MTU":1500,"Name":"en1","HardwareAddr":"NshwKFsA","Flags":51,"AltAddrs":null,"Desc":""},"en2":{"Index":11,"MTU":1500,"Name":"en2","HardwareAddr":"NshwKFsE","Flags":51,"AltAddrs":null,"Desc":""},"en3":{"Index":12,"MTU":1500,"Name":"en3","HardwareAddr":"NshwKFsI","Flags":51,"AltAddrs":null,"Desc":""},"en4":{"Index":7,"MTU":1500,"Name":"en4","HardwareAddr":"7pFxPWhi","Flags":51,"AltAddrs":null,"Desc":""},"en5":{"Index":8,"MTU":1500,"Name":"en5","HardwareAddr":"7pFxPWhj","Flags":51,"AltAddrs":null,"Desc":""},"en6":{"Index":9,"MTU":1500,"Name":"en6","HardwareAddr":"7pFxPWhk","Flags":51,"AltAddrs":null,"Desc":""},"gif0":{"Index":2,"MTU":1280,"Name":"gif0","HardwareAddr":null,"Flags":24,"AltAddrs":null,"Desc":""},"llw0":{"Index":17,"MTU":1500,"Name":"llw0","HardwareAddr":"EiNxgfED","Flags":51,"AltAddrs":null,"Desc":""},"lo0":{"Index":1,"MTU":16384,"Name":"lo0","HardwareAddr":null,"Flags":53,"AltAddrs":null,"Desc":""},"stf0":{"Index":3,"MTU":1280,"Name":"stf0","HardwareAddr":null,"Flags":0,"AltAddrs":null,"Desc":""},"utun0":{"Index":18,"MTU":1500,"Name":"utun0","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun1":{"Index":19,"MTU":1380,"Name":"utun1","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun2":{"Index":20,"MTU":2000,"Name":"utun2","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun3":{"Index":21,"MTU":1000,"Name":"utun3","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun4":{"Index":22,"MTU":1500,"Name":"utun4","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""}},"HaveV6":true,"HaveV4":true,"IsExpensive":false,"DefaultRouteInterface":"en0","HTTPProxy":"","PAC":""}
monitor: [unexpected] new: {"InterfaceIPs":{"anpi0":null,"anpi1":null,"anpi2":null,"ap1":["fe80::7ce9:1eff:feb1:3a9d/64"],"awdl0":["fe80::1023:71ff:fe81:f103/64"],"bridge0":null,"en0":["192.168.178.20/24","fd1a:a7fd:a1cc:c24b:185e:b60:6e1c:164f/64","fe80::1870:9300:3ebd:c9cf/64"],"en1":null,"en2":null,"en3":null,"en4":null,"en5":null,"en6":null,"gif0":null,"llw0":["fe80::1023:71ff:fe81:f103/64"],"lo0":["127.0.0.1/8","::1/128","fe80::1/64"],"stf0":null,"utun0":["fe80::d80f:4c5e:18ef:6e26/64"],"utun1":["fe80::f171:5d23:c04f:b113/64"],"utun2":["fe80::6a0c:bc60:9cd1:4e48/64"],"utun3":["fe80::ce81:b1c:bd2c:69e/64"],"utun4":null},"Interface":{"anpi0":{"Index":6,"MTU":1500,"Name":"anpi0","HardwareAddr":"7pFxPWiC","Flags":51,"AltAddrs":null,"Desc":""},"anpi1":{"Index":4,"MTU":1500,"Name":"anpi1","HardwareAddr":"7pFxPWiD","Flags":51,"AltAddrs":null,"Desc":""},"anpi2":{"Index":5,"MTU":1500,"Name":"anpi2","HardwareAddr":"7pFxPWiE","Flags":51,"AltAddrs":null,"Desc":""},"ap1":{"Index":14,"MTU":1500,"Name":"ap1","HardwareAddr":"fukesTqd","Flags":51,"AltAddrs":null,"Desc":""},"awdl0":{"Index":16,"MTU":1500,"Name":"awdl0","HardwareAddr":"EiNxgfED","Flags":51,"AltAddrs":null,"Desc":""},"bridge0":{"Index":13,"MTU":1500,"Name":"bridge0","HardwareAddr":"NshwKFsA","Flags":51,"AltAddrs":null,"Desc":""},"en0":{"Index":15,"MTU":1500,"Name":"en0","HardwareAddr":"XOkesTqd","Flags":51,"AltAddrs":null,"Desc":""},"en1":{"Index":10,"MTU":1500,"Name":"en1","HardwareAddr":"NshwKFsA","Flags":51,"AltAddrs":null,"Desc":""},"en2":{"Index":11,"MTU":1500,"Name":"en2","HardwareAddr":"NshwKFsE","Flags":51,"AltAddrs":null,"Desc":""},"en3":{"Index":12,"MTU":1500,"Name":"en3","HardwareAddr":"NshwKFsI","Flags":51,"AltAddrs":null,"Desc":""},"en4":{"Index":7,"MTU":1500,"Name":"en4","HardwareAddr":"7pFxPWhi","Flags":51,"AltAddrs":null,"Desc":""},"en5":{"Index":8,"MTU":1500,"Name":"en5","HardwareAddr":"7pFxPWhj","Flags":51,"AltAddrs":null,"Desc":""},"en6":{"Index":9,"MTU":1500,"Name":"en6","HardwareAddr":"7pFxPWhk","Flags":51,"AltAddrs":null,"Desc":""},"gif0":{"Index":2,"MTU":1280,"Name":"gif0","HardwareAddr":null,"Flags":24,"AltAddrs":null,"Desc":""},"llw0":{"Index":17,"MTU":1500,"Name":"llw0","HardwareAddr":"EiNxgfED","Flags":51,"AltAddrs":null,"Desc":""},"lo0":{"Index":1,"MTU":16384,"Name":"lo0","HardwareAddr":null,"Flags":53,"AltAddrs":null,"Desc":""},"stf0":{"Index":3,"MTU":1280,"Name":"stf0","HardwareAddr":null,"Flags":0,"AltAddrs":null,"Desc":""},"utun0":{"Index":18,"MTU":1500,"Name":"utun0","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun1":{"Index":19,"MTU":1380,"Name":"utun1","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun2":{"Index":20,"MTU":2000,"Name":"utun2","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun3":{"Index":21,"MTU":1000,"Name":"utun3","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""},"utun4":{"Index":22,"MTU":1280,"Name":"utun4","HardwareAddr":null,"Flags":57,"AltAddrs":null,"Desc":""}},"HaveV6":true,"HaveV4":true,"IsExpensive":false,"DefaultRouteInterface":"en0","HTTPProxy":"","PAC":""}
LinkChange: major, rebinding. New state: interfaces.State{defaultRoute=en0 ifs={en0:[192.168.178.20/24 fd1a:a7fd:a1cc:c24b:185e:b60:6e1c:164f/64 llu6]} v4=true v6=true}
dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}
dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}
dns: OScfg: {}
wgengine: set DNS config again after major link change
onPortUpdate(port=41641, network=udp6)
onPortUpdate(port=41641, network=udp4)
Rebind; defIf="en0", ips=[192.168.178.20/24 fd1a:a7fd:a1cc:c24b:185e:b60:6e1c:164f/64 fe80::1870:9300:3ebd:c9cf/64]
magicsock: 0 active derp conns
monitor: gateway and self IP changed: gw=192.168.178.1 self=192.168.178.20
portmapper: failed to get PCP mapping: Does not appear to be PCP MAP response
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
up=1715797146+10 Sys=14.1M HeapAlloc=2.7M HeapSys=6.9M HeapIdle=2.3M HeapInuse=4.6M HeapReleased=0.9M StackInuse=1.1M StackSys=1.1M MSpanInuse=0.1M MSpanSys=0.1M BuckHashSys=1.4M GCSys=2.9M OtherSys=1.7M NumGC=4 cpuU=87969000 cpuS=59672000 goroutines=83
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
EditPrefs: MaskedPrefs{WantRunning=true}
Keychain.loadData: tailscale-profiles, found
Keychain.loadData: tailscale-profiles, success, found 302 bytes
Keychain.loadData: tailscale-current-profile, found
Keychain.loadData: tailscale-current-profile, success, found 12 bytes
Keychain.loadData: tailscale-id-profile-a443, found
Keychain.loadData: tailscale-id-profile-a443, success, found 1274 bytes
Keychain.saveData: update tailscale-id-profile-a443: success, saved 1273 bytes
transitioning to running; doing Login...
control: client.Login(false, 0)
Switching ipn state Stopped -> Starting (WantRunning=true, nm=false)
control: doLogin(regen=false, hasUrl=false)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=false nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
control: doLogin(regen=false, hasUrl=true)
Received auth URL: https://hs.<domain>...
Switching ipn state Starting -> NeedsLogin (WantRunning=true, nm=false)
blockEngineUpdates(true)
Reconfig(down): no changes made to Engine config
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
control: RegisterReq: got response; nodeKeyExpired=false, machineAuthorized=false; authURL=true
control: AuthURL is https://hs.<domain>/oidc/register/mkey:<nodekey>
Received auth URL: https://hs.<domain>...
control: doLogin(regen=false, hasUrl=true)
control: control server key from https://hs.<domain>: ts2021=[CXTnx], legacy=
control: RegisterReq: onode=[pCs1n] node=[g94TE] fup=true nks=false
^C
(3.11) mac: ~ %

[casdr]

When I try to delete an affected node in Headscale, I'm getting the following error:

root@hs:~# headscale node del -i 28
Error getting node node: context deadline exceeded

After a restart of Headscale, it works fine.

[winterheart]

This is issue is same as #1930.

Problem may occur on any client regardless to OS. Restarting headscale temporarily solves connection problem.

[casdr]

@winterheart that seems correct. Somehow GitHub didn't show that issue when searching for the error in the log.

[Mark3xtrm]

This happens to me as well. Or at least something similar (?)

My headscale is on an i386 netbook with Debian GNU/Linux 11 (bullseye) i686.

Whatever method I use to register my nodes (browser, or auth key), whatever is their type (Linux, Android, Windows, iOS), they all start up offline since headscale starts.

Of course I choose for my headscale URL a free port.

● headscale.service - headscale coordination server for Tailscale
     Loaded: loaded (/lib/systemd/system/headscale.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2024-05-17 15:09:19 CEST; 16min ago
   Main PID: 15729 (headscale)
      Tasks: 8 (limit: 4640)
     Memory: 17.5M
     CGroup: /system.slice/headscale.service
             └─15729 /usr/bin/headscale serve

mag 17 15:19:55 <my_hostname> headscale[15729]: 2024-05-17T15:19:55+02:00 INF ../../../home/runner/work/headscale/headscale/hscontrol/poll.go:657 > node has an open stream(0xb9a4c38), rejecting new stream node=Desktop node.id=13 omitPeers=false readOnly=false stream=true
[trimmed, same story]
mag 17 15:24:40 <my_hostname> headscale[15729]: 2024-05-17T15:24:40+02:00 INF ../../../home/runner/work/headscale/headscale/hscontrol/poll.go:657 > node has an open stream(0xba54878), rejecting new stream node=Desktop node.id=13 omitPeers=false readOnly=false stream=true
mag 17 15:25:17 <my_hostname> headscale[15729]: 2024-05-17T15:25:17+02:00 INF ../../../home/runner/work/headscale/headscale/hscontrol/poll.go:657 > node has an open stream(0xb9ac698), rejecting new stream node=Desktop node.id=13 omitPeers=false readOnly=false stream=true

My nodes list

2024-05-17T15:37:37+02:00 TRC DNS configuration loaded dns_config={"Nameservers":["1.1.1.1"],"Proxied":true,"Resolvers":[{"Addr":"1.1.1.1"}]}
2024-05-17T15:37:38+02:00 WRN An updated version of Headscale has been found (0.23.0-alpha9 vs. your current v0.23.0-alpha11). Check it out https://github.com/juanfont/headscale/releases

ID | Hostname     | Name              | MachineKey | NodeKey | User       | IP addresses                  | Ephemeral | Last seen           | Expiration          | Connected | Expired
---|--------------|-------------------|------------|---------|------------|------------------------------|-----------|---------------------|---------------------|-----------|--------
8  | <Device_name> | <device-name>     | [f2VEm]    | [nb5zR] | computer   | 100.64.0.1, fd7a:115c:a1e0::1 | false     | 2024-04-30 16:34:01 | 0001-01-01 00:00:00 | offline   | no
9  | <Device_name> | <device-name>     | [KEpzA]    | [tuyKz] | smartphone | 100.64.0.2, fd7a:115c:a1e0::2 | false     | 2024-04-30 16:34:17 | 0001-01-01 00:00:00 | offline   | no
10 | <Device_name> | <device-name>     | [sq9LM]    | [llJiZ] | smartphone | 100.64.0.3, fd7a:115c:a1e0::3 | false     | 2024-05-14 22:42:48 | 0001-01-01 00:00:00 | offline   | no
11 | <Device_name> | <device-name>-h169yrfc | [RvuMh] | [3v6Yb] | smartphone | 100.64.0.4, fd7a:115c:a1e0::4 | false     | 2024-05-15 00:17:38 | 0001-01-01 00:00:00 | offline   | no
12 | <Device_name> | <device-name>-n42eodcs | [JHj4f] | [LImo5] | smartphone | 100.64.0.5, fd7a:115c:a1e0::5 | false     | 2024-05-15 00:22:12 | 0001-01-01 00:00:00 | offline   | no
13 | <Device_name> | <device-name>     | [rt2q8]    | [RxoyX] | computer   | 100.64.0.6, fd7a:115c:a1e0::6 | false     | 2024-05-17 13:09:22 | 0001-01-01 00:00:00 | offline   | no

[jaen]

I also had a similar issue just now, first time it happened, though it seems my Tailscale is a bit less reliable recently.

All my traffic from my phone (Android) is shuttled through an exit node. I was playing some Genshin Impact when the game disconnected. After restarting the game, I couldn't even login. Then I tried to access anything in my browser (both pages on the wide web as well as those I have behind the VPN) and nothing connected either. Restarting the phone and trying to reconnect to the VPN produced the same "node has an open stream" as above. Restarting headscale helped.

The other bug was closed after someone suggested updating the Android client to 1.66.3, but I'm already at that version. Headscale is up to date. Let me know if there's anything else that would be helpful to provide.