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

Log flood #340

New Issue
Closed
opened 2025-12-29 01:27:20 +01:00 by adam · 3 comments
adam commented 2025-12-29 01:27:20 +01:00
Owner
Copy Link

Originally created by @mhameed on GitHub (Sep 27, 2022).

Hi,

I have about 50 lxc containers distributed amongst diffrent hypervisors, all using tailscale to provide a private network amongst themselves.

Unfortunately both the tailscale nodes and the headscale server are producing copious amounts of logging.

on the headscale server (v0.17.0-alfa2) I have logs such as:

Sep 27 00:00:00 headscale headscale[575]: 2022-09-27T00:00:00+01:00 INF The client has closed the connection handler=PollNetMapStream machine=u
Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=cl noise=true
Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 INF Sending initial map handler=PollNetMap machine=cl noise=true
Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 INF Notifying peers handler=PollNetMap machine=cl noise=true
Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 ERR Cannot write data error="http2: stream closed" channel=pollData handler=PollNetMapStream machine=cl noise=true
Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF The client has closed the connection handler=PollNetMapStream machine=h3
Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=th noise=true
Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF Sending initial map handler=PollNetMap machine=th noise=true
Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF Notifying peers handler=PollNetMap machine=th noise=true
Sep 27 00:00:06 headscale headscale[575]: 2022-09-27T00:00:06+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=na noise=true
Sep 27 00:00:06 headscale headscale[575]: 2022-09-27T00:00:06+01:00 INF Sending initial map handler=PollNetMap machine=na noise=true
Sep 27 00:00:06 headscale headscale[575]: 2022-09-27T00:00:06+01:00 INF Notifying peers handler=PollNetMap machine=na noise=true
Sep 27 00:00:07 headscale headscale[575]: 2022-09-27T00:00:07+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=os noise=true
Sep 27 00:00:07 headscale headscale[575]: 2022-09-27T00:00:07+01:00 INF Sending initial map handler=PollNetMap machine=os noise=true
Sep 27 00:00:07 headscale headscale[575]: 2022-09-27T00:00:07+01:00 INF Notifying peers handler=PollNetMap machine=os noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=nh noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Sending initial map handler=PollNetMap machine=nh noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Notifying peers handler=PollNetMap machine=nh noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=ts noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Sending initial map handler=PollNetMap machine=ts noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Notifying peers handler=PollNetMap machine=ts noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF The client has closed the connection handler=PollNetMapStream machine=phassage
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF The client has closed the connection handler=PollNetMapStream machine=md
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF The client has closed the connection handler=PollNetMapStream machine=rf
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=lv noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Sending initial map handler=PollNetMap machine=lv noise=true
Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Notifying peers handler=PollNetMap machine=lv noise=true
Sep 27 00:00:09 headscale headscale[575]: 2022-09-27T00:00:09+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=lr noise=true
Sep 27 00:00:09 headscale headscale[575]: 2022-09-27T00:00:09+01:00 INF Sending initial map handler=PollNetMap machine=lr noise=true
Sep 27 00:00:09 headscale headscale[575]: 2022-09-27T00:00:09+01:00 INF Notifying peers handler=PollNetMap machine=lr noise=true
Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF The client has closed the connection handler=PollNetMapStream machine=lr
Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=h noise=true
Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF Sending initial map handler=PollNetMap machine=h noise=true
Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF Notifying peers handler=PollNetMap machine=h noise=true
Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF The client has closed the connection handler=PollNetMapStream machine=h
Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=ga noise=true
Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF Sending initial map handler=PollNetMap machine=ga noise=true
Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF Notifying peers handler=PollNetMap machine=ga noise=true
Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF The client has closed the connection handler=PollNetMapStream machine=ga

for a full 24 hr period, I have almost half a million lines of the above.

The respective log on a tailscale node (1.30.2) looks something like:

Sep 27 00:00:01 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:00:06 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn
Sep 27 00:00:18 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:00:21 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 315 tcp non-syn
Sep 27 00:00:21 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out
Sep 27 00:00:36 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn
Sep 27 00:00:38 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:00:44 cl tailscaled[150]: Accept: TCP{100.64.0.13:39420 > 100.64.0.40:25} 60 tcp ok
Sep 27 00:00:51 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out
Sep 27 00:01:07 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn
Sep 27 00:01:09 cl tailscaled[150]: health("overall"): ok
Sep 27 00:01:19 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:01:21 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 315 tcp non-syn
Sep 27 00:01:21 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out
Sep 27 00:01:31 cl tailscaled[150]: health("overall"): error: not in map poll
Sep 27 00:01:36 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn
Sep 27 00:01:45 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:01:45 cl tailscaled[150]: Accept: TCP{100.64.0.13:38476 > 100.64.0.40:25} 60 tcp ok
Sep 27 00:01:51 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn
Sep 27 00:02:11 cl tailscaled[150]: health("overall"): ok
Sep 27 00:02:21 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 315 tcp non-syn
Sep 27 00:02:21 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out
Sep 27 00:02:21 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:02:33 cl tailscaled[150]: health("overall"): error: not in map poll
Sep 27 00:02:36 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn
Sep 27 00:02:38 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch
Sep 27 00:02:42 cl tailscaled[150]: Accept: TCP{100.64.0.13:34472 > 100.64.0.40:25} 60 tcp ok
Sep 27 00:02:51 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out
Sep 27 00:03:02 cl tailscaled[150]: health("overall"): ok

On each tailscale node, we have about 18000 lines of the above per day.

Thanks for any advice.

Originally created by @mhameed on GitHub (Sep 27, 2022). Hi, I have about 50 lxc containers distributed amongst diffrent hypervisors, all using tailscale to provide a private network amongst themselves. Unfortunately both the tailscale nodes and the headscale server are producing copious amounts of logging. on the headscale server (v0.17.0-alfa2) I have logs such as: Sep 27 00:00:00 headscale headscale[575]: 2022-09-27T00:00:00+01:00 INF The client has closed the connection handler=PollNetMapStream machine=u Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=cl noise=true Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 INF Sending initial map handler=PollNetMap machine=cl noise=true Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 INF Notifying peers handler=PollNetMap machine=cl noise=true Sep 27 00:00:01 headscale headscale[575]: 2022-09-27T00:00:01+01:00 ERR Cannot write data error="http2: stream closed" channel=pollData handler=PollNetMapStream machine=cl noise=true Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF The client has closed the connection handler=PollNetMapStream machine=h3 Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=th noise=true Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF Sending initial map handler=PollNetMap machine=th noise=true Sep 27 00:00:05 headscale headscale[575]: 2022-09-27T00:00:05+01:00 INF Notifying peers handler=PollNetMap machine=th noise=true Sep 27 00:00:06 headscale headscale[575]: 2022-09-27T00:00:06+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=na noise=true Sep 27 00:00:06 headscale headscale[575]: 2022-09-27T00:00:06+01:00 INF Sending initial map handler=PollNetMap machine=na noise=true Sep 27 00:00:06 headscale headscale[575]: 2022-09-27T00:00:06+01:00 INF Notifying peers handler=PollNetMap machine=na noise=true Sep 27 00:00:07 headscale headscale[575]: 2022-09-27T00:00:07+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=os noise=true Sep 27 00:00:07 headscale headscale[575]: 2022-09-27T00:00:07+01:00 INF Sending initial map handler=PollNetMap machine=os noise=true Sep 27 00:00:07 headscale headscale[575]: 2022-09-27T00:00:07+01:00 INF Notifying peers handler=PollNetMap machine=os noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=nh noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Sending initial map handler=PollNetMap machine=nh noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Notifying peers handler=PollNetMap machine=nh noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=ts noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Sending initial map handler=PollNetMap machine=ts noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Notifying peers handler=PollNetMap machine=ts noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF The client has closed the connection handler=PollNetMapStream machine=phassage Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF The client has closed the connection handler=PollNetMapStream machine=md Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF The client has closed the connection handler=PollNetMapStream machine=rf Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=lv noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Sending initial map handler=PollNetMap machine=lv noise=true Sep 27 00:00:08 headscale headscale[575]: 2022-09-27T00:00:08+01:00 INF Notifying peers handler=PollNetMap machine=lv noise=true Sep 27 00:00:09 headscale headscale[575]: 2022-09-27T00:00:09+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=lr noise=true Sep 27 00:00:09 headscale headscale[575]: 2022-09-27T00:00:09+01:00 INF Sending initial map handler=PollNetMap machine=lr noise=true Sep 27 00:00:09 headscale headscale[575]: 2022-09-27T00:00:09+01:00 INF Notifying peers handler=PollNetMap machine=lr noise=true Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF The client has closed the connection handler=PollNetMapStream machine=lr Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=h noise=true Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF Sending initial map handler=PollNetMap machine=h noise=true Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF Notifying peers handler=PollNetMap machine=h noise=true Sep 27 00:00:10 headscale headscale[575]: 2022-09-27T00:00:10+01:00 INF The client has closed the connection handler=PollNetMapStream machine=h Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF Client is ready to access the tailnet handler=PollNetMap machine=ga noise=true Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF Sending initial map handler=PollNetMap machine=ga noise=true Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF Notifying peers handler=PollNetMap machine=ga noise=true Sep 27 00:00:11 headscale headscale[575]: 2022-09-27T00:00:11+01:00 INF The client has closed the connection handler=PollNetMapStream machine=ga for a full 24 hr period, I have almost half a million lines of the above. The respective log on a tailscale node (1.30.2) looks something like: Sep 27 00:00:01 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:00:06 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn Sep 27 00:00:18 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:00:21 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 315 tcp non-syn Sep 27 00:00:21 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out Sep 27 00:00:36 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn Sep 27 00:00:38 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:00:44 cl tailscaled[150]: Accept: TCP{100.64.0.13:39420 > 100.64.0.40:25} 60 tcp ok Sep 27 00:00:51 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out Sep 27 00:01:07 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn Sep 27 00:01:09 cl tailscaled[150]: health("overall"): ok Sep 27 00:01:19 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:01:21 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 315 tcp non-syn Sep 27 00:01:21 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out Sep 27 00:01:31 cl tailscaled[150]: health("overall"): error: not in map poll Sep 27 00:01:36 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn Sep 27 00:01:45 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:01:45 cl tailscaled[150]: Accept: TCP{100.64.0.13:38476 > 100.64.0.40:25} 60 tcp ok Sep 27 00:01:51 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn Sep 27 00:02:11 cl tailscaled[150]: health("overall"): ok Sep 27 00:02:21 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 315 tcp non-syn Sep 27 00:02:21 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out Sep 27 00:02:21 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:02:33 cl tailscaled[150]: health("overall"): error: not in map poll Sep 27 00:02:36 cl tailscaled[150]: Accept: TCP{100.64.0.48:45882 > 100.64.0.40:9469} 52 tcp non-syn Sep 27 00:02:38 cl tailscaled[150]: Received error: PollNetMap: invalid input: magic number mismatch Sep 27 00:02:42 cl tailscaled[150]: Accept: TCP{100.64.0.13:34472 > 100.64.0.40:25} 60 tcp ok Sep 27 00:02:51 cl tailscaled[150]: Accept: TCP{100.64.0.40:9469 > 100.64.0.48:45882} 52 ok out Sep 27 00:03:02 cl tailscaled[150]: health("overall"): ok On each tailscale node, we have about 18000 lines of the above per day. Thanks for any advice.
adam added the bug label 2025-12-29 01:27:20 +01:00
adam closed this issue 2025-12-29 01:27:20 +01:00
adam commented 2025-12-29 01:27:21 +01:00
Author
Owner
Copy Link

@samcday commented on GitHub (Oct 15, 2022):

I ran into this tonight as well. For me only some nodes were affected, and the issue went away after a combination of tailscale down && tailscale up and/or systemctl restart tailscaled... which makes me think this might be a tailscale client bug rather than a headscale issue?

@samcday commented on GitHub (Oct 15, 2022): I ran into this tonight as well. For me only some nodes were affected, and the issue went away after a combination of `tailscale down && tailscale up` and/or `systemctl restart tailscaled`... which makes me think this might be a tailscale client bug rather than a headscale issue?
adam commented 2025-12-29 01:27:21 +01:00
Author
Owner
Copy Link

@iSchluff commented on GitHub (Nov 10, 2022):

@kradalby The error seems to coming from the to the zstd decoder in the PollNetMap client code.
3909335c44/zstd/zstd.go (L64)

I guess its expecting compressed data, but we are not sending any

@iSchluff commented on GitHub (Nov 10, 2022): @kradalby The error seems to coming from the to the zstd decoder in the PollNetMap client code. https://github.com/klauspost/compress/blob/3909335c441d115103e37728040269eae87df317/zstd/zstd.go#L64 I guess its expecting compressed data, but we are not sending any
adam commented 2025-12-29 01:27:22 +01:00
Author
Owner
Copy Link

@iSchluff commented on GitHub (Nov 10, 2022):

I captured a trace log from the server, showing the noise exchange. The error occurs always on the first NetMap update after the initial map has been sent.

headscale 2022-11-10T11:37:59Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC Finished stream, closing PollNetMap session handler=PollNetMap machine=ans-wup noise=true
headscale 2022-11-10T11:37:59Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=ans-wup
headscale 2022-11-10T11:37:59Z INF The client has closed the connection handler=PollNetMapStream machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:59Z TRC Generated map response: { Node: ans-wup-m7avc02g.mydomain, Peers: [...](45) } func=generateMapResponse machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:302 > Found total peers: [...](45) machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:241 > Found some machines: [...] machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:174 > Finding peers filtered by ACLs machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC Creating Map response func=generateMapResponse machine=ans-wup
headscale 2022-11-10T11:37:59Z DBG There has been updates since the last successful update to ans-wup handler=PollNetMapStream last_state_change=1668080278 last_successful_update=1668080259 machine=ans-wup noise=true
headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:564 > Checking if ans-wup is missing updates last_state_change=1668080259 last_successful_update=1668080278 machine=ans-wup
headscale 2022-11-10T11:37:59Z TRC Received a request for update channel=update handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:59Z DBG Sending update request func=scheduledPollWorker machine=ans-wup noise=true
headscale 2022-11-10T11:37:49Z TRC ans-wup is up to date handler=PollNetMapStream last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup noise=true
headscale 2022-11-10T11:37:49Z TRC go/src/headscale/machine.go:564 > Checking if ans-wup is missing updates last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup
headscale 2022-11-10T11:37:49Z TRC Received a request for update channel=update handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:49Z DBG Sending update request func=scheduledPollWorker machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC ans-wup is up to date handler=PollNetMapStream last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:564 > Checking if ans-wup is missing updates last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup
headscale 2022-11-10T11:37:39Z TRC Received a request for update channel=update handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC Machine entry in database updated successfully after sending data bytes=21343 channel=pollData handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC Data from pollData channel written successfully bytes=21343 channel=pollData handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC Sending data received via pollData channel bytes=21343 channel=pollData handler=PollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC pollData is (chan []uint8)(0xc0002098c0), keepAliveChan is (chan []uint8)(0xc00063a1e0), updateChan is (chan struct {})(0xc00063a180) handler=pollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC Waiting for data to stream... handler=pollNetMapStream machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z INF Notifying peers handler=PollNetMap machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z INF Sending initial map handler=PollNetMap machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z INF Client is ready to access the tailnet handler=PollNetMap machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z TRC go/src/headscale/protocol_common_poll.go:139 > Loading or creating update channel machine=ans-wup noise=true
headscale 2022-11-10T11:37:39Z DBG Client map request processed handler=PollNetMap machine=ans-wup noise=true omitPeers=false readOnly=false stream=true
headscale 2022-11-10T11:37:39Z TRC Generated map response: { Node: ans-wup-m7avc02g.mydomain, Peers: [...](45) } func=generateMapResponse machine=ans-wup
headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:302 > Found total Peers: [...](45) machine=ans-wup
headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:241 > Found some machines: [...] machine=ans-wup
headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:174 > Finding peers filtered by ACLs machine=ans-wup
headscale 2022-11-10T11:37:39Z TRC Creating Map response func=generateMapResponse machine=ans-wup
headscale 2022-11-10T11:37:39Z DBG A machine is entering polling via the Noise protocol handler=NoisePollNetMap machine=ans-wup
@iSchluff commented on GitHub (Nov 10, 2022): I captured a trace log from the server, showing the noise exchange. The error occurs always on the first NetMap update after the initial map has been sent. ``` headscale 2022-11-10T11:37:59Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=ans-wup headscale 2022-11-10T11:37:59Z TRC Finished stream, closing PollNetMap session handler=PollNetMap machine=ans-wup noise=true headscale 2022-11-10T11:37:59Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=ans-wup headscale 2022-11-10T11:37:59Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=ans-wup headscale 2022-11-10T11:37:59Z INF The client has closed the connection handler=PollNetMapStream machine=ans-wup headscale 2022-11-10T11:37:59Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:59Z TRC Generated map response: { Node: ans-wup-m7avc02g.mydomain, Peers: [...](45) } func=generateMapResponse machine=ans-wup headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:302 > Found total peers: [...](45) machine=ans-wup headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:241 > Found some machines: [...] machine=ans-wup headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:174 > Finding peers filtered by ACLs machine=ans-wup headscale 2022-11-10T11:37:59Z TRC Creating Map response func=generateMapResponse machine=ans-wup headscale 2022-11-10T11:37:59Z DBG There has been updates since the last successful update to ans-wup handler=PollNetMapStream last_state_change=1668080278 last_successful_update=1668080259 machine=ans-wup noise=true headscale 2022-11-10T11:37:59Z TRC go/src/headscale/machine.go:564 > Checking if ans-wup is missing updates last_state_change=1668080259 last_successful_update=1668080278 machine=ans-wup headscale 2022-11-10T11:37:59Z TRC Received a request for update channel=update handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:59Z DBG Sending update request func=scheduledPollWorker machine=ans-wup noise=true headscale 2022-11-10T11:37:49Z TRC ans-wup is up to date handler=PollNetMapStream last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup noise=true headscale 2022-11-10T11:37:49Z TRC go/src/headscale/machine.go:564 > Checking if ans-wup is missing updates last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup headscale 2022-11-10T11:37:49Z TRC Received a request for update channel=update handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:49Z DBG Sending update request func=scheduledPollWorker machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC ans-wup is up to date handler=PollNetMapStream last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:564 > Checking if ans-wup is missing updates last_state_change=1668080259 last_successful_update=1668080259 machine=ans-wup headscale 2022-11-10T11:37:39Z TRC Received a request for update channel=update handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC Machine entry in database updated successfully after sending data bytes=21343 channel=pollData handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC Data from pollData channel written successfully bytes=21343 channel=pollData handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC Sending data received via pollData channel bytes=21343 channel=pollData handler=PollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC pollData is (chan []uint8)(0xc0002098c0), keepAliveChan is (chan []uint8)(0xc00063a1e0), updateChan is (chan struct {})(0xc00063a180) handler=pollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC Waiting for data to stream... handler=pollNetMapStream machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z INF Notifying peers handler=PollNetMap machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z INF Sending initial map handler=PollNetMap machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z INF Client is ready to access the tailnet handler=PollNetMap machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z TRC go/src/headscale/protocol_common_poll.go:139 > Loading or creating update channel machine=ans-wup noise=true headscale 2022-11-10T11:37:39Z DBG Client map request processed handler=PollNetMap machine=ans-wup noise=true omitPeers=false readOnly=false stream=true headscale 2022-11-10T11:37:39Z TRC Generated map response: { Node: ans-wup-m7avc02g.mydomain, Peers: [...](45) } func=generateMapResponse machine=ans-wup headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:302 > Found total Peers: [...](45) machine=ans-wup headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:241 > Found some machines: [...] machine=ans-wup headscale 2022-11-10T11:37:39Z TRC go/src/headscale/machine.go:174 > Finding peers filtered by ACLs machine=ans-wup headscale 2022-11-10T11:37:39Z TRC Creating Map response func=generateMapResponse machine=ans-wup headscale 2022-11-10T11:37:39Z DBG A machine is entering polling via the Noise protocol handler=NoisePollNetMap machine=ans-wup ```
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
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#340
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?