panic: send on closed channel #131

Closed
opened 2025-12-29 01:23:40 +01:00 by adam · 11 comments
Owner

Originally created by @nblock on GitHub (Feb 21, 2022).

Bug description

Crash of headscale serve after a while:

[GIN] 2022/02/19 - 18:57:18 | 200 |    9.680593ms |  aa.bb.cc.dd | POST     "/machine/UUID1/map"
2022-02-19T18:57:19Z INF Client sent endpoint update and is ok with a response without peer list handler=PollNetMap machine=H1
[GIN] 2022/02/19 - 18:57:19 | 200 |    7.772691ms |  aa.bb.cc.dd | POST     "/machine/UUID1/map"
[GIN] 2022/02/19 - 19:55:39 | 200 |       2h10m5s | aa.bb.cc.dd | POST     "/machine/UUID1/map"
panic: send on closed channel

goroutine 1079 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x44ec45, {0x1245a50, 0xc000078f00}, _, _, {{0x9e, 0xc7, 0x46, 0x18, 0xed, ...}}, ...)
        /home/runner/work/headscale/headscale/poll.go:578 +0x3ad
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
        /home/runner/work/headscale/headscale/poll.go:261 +0x24b
  • The duration of the last entry is interesting - 2h10m5s.
  • The machine in question is regularly suspended/powered off

Context info

  • Headscale v0.13.0 and v0.14.0
  • Ubuntu 20.04
Originally created by @nblock on GitHub (Feb 21, 2022). **Bug description** Crash of `headscale serve` after a while: ``` [GIN] 2022/02/19 - 18:57:18 | 200 | 9.680593ms | aa.bb.cc.dd | POST "/machine/UUID1/map" 2022-02-19T18:57:19Z INF Client sent endpoint update and is ok with a response without peer list handler=PollNetMap machine=H1 [GIN] 2022/02/19 - 18:57:19 | 200 | 7.772691ms | aa.bb.cc.dd | POST "/machine/UUID1/map" [GIN] 2022/02/19 - 19:55:39 | 200 | 2h10m5s | aa.bb.cc.dd | POST "/machine/UUID1/map" panic: send on closed channel goroutine 1079 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x44ec45, {0x1245a50, 0xc000078f00}, _, _, {{0x9e, 0xc7, 0x46, 0x18, 0xed, ...}}, ...) /home/runner/work/headscale/headscale/poll.go:578 +0x3ad created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /home/runner/work/headscale/headscale/poll.go:261 +0x24b ``` * The duration of the last entry is interesting - 2h10m5s. * The machine in question is regularly suspended/powered off **Context info** - Headscale v0.13.0 and v0.14.0 - Ubuntu 20.04
adam added the bug label 2025-12-29 01:23:40 +01:00
adam closed this issue 2025-12-29 01:23:40 +01:00
Author
Owner

@allastornin commented on GitHub (Feb 28, 2022):

I ran into the danger problem too:

panic: send on closed channel

goroutine 5023 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x44ec45, {0x1245a50, 0xc00072d980}, _, _, {{0x63, 0xd, 0x81, 0xb7, 0xf0, ...}}, ...)
/home/runner/work/headscale/headscale/poll.go:578 +0x3ad
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
/home/runner/work/headscale/headscale/poll.go:261 +0x24b

@allastornin commented on GitHub (Feb 28, 2022): I ran into the danger problem too: panic: send on closed channel goroutine 5023 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x44ec45, {0x1245a50, 0xc00072d980}, _, _, {{0x63, 0xd, 0x81, 0xb7, 0xf0, ...}}, ...) /home/runner/work/headscale/headscale/poll.go:578 +0x3ad created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /home/runner/work/headscale/headscale/poll.go:261 +0x24b
Author
Owner

@gabm commented on GitHub (Mar 9, 2022):

I ran into this as well. It does not have to do with suspend/resume as my machine kept running all the time

@gabm commented on GitHub (Mar 9, 2022): I ran into this as well. It does not have to do with suspend/resume as my machine kept running all the time
Author
Owner

@huskyii commented on GitHub (Mar 14, 2022):

@gabm @allastornin @nblock

Hi guys, are you using old machine to run headscale? or was the machine heavy loaded?
And please turn on TRACE level log and paste it here if possible.

I did some preliminary RCA, and found it may due to lag between case <-keepAliveTicker.C and keepAliveChan <- data.

If the execution sequence is as follows, headscale may panic:

1) keepAliveChan is empty
2) case <-keepAliveTicker.C
3) ctx.Stream slects on channels, and nothing to do thus returned
4) keepAliveChan closed
5) keepAliveChan <- data
@huskyii commented on GitHub (Mar 14, 2022): @gabm @allastornin @nblock Hi guys, are you using old machine to run headscale? or was the machine heavy loaded? And please turn on TRACE level log and paste it here if possible. I did some preliminary RCA, and found it may due to lag between `case <-keepAliveTicker.C` and `keepAliveChan <- data`. If the execution sequence is as follows, headscale may panic: ``` 1) keepAliveChan is empty 2) case <-keepAliveTicker.C 3) ctx.Stream slects on channels, and nothing to do thus returned 4) keepAliveChan closed 5) keepAliveChan <- data ```
Author
Owner

@nblock commented on GitHub (Mar 14, 2022):

Hi guys, are you using old machine to run headscale? or was the machine heavy loaded? And please turn on TRACE level log and paste it here if possible.

Just a dedicated (but small) VM with just headscale and nginx as reverse proxy. Will increase log verbosity and report back, in case there is something interesting.

@nblock commented on GitHub (Mar 14, 2022): > Hi guys, are you using old machine to run headscale? or was the machine heavy loaded? And please turn on TRACE level log and paste it here if possible. Just a dedicated (but small) VM with just headscale and nginx as reverse proxy. Will increase log verbosity and report back, in case there is something interesting.
Author
Owner

@ash0x72 commented on GitHub (Mar 19, 2022):

 [GIN] 2022/03/19 - 10:30:20 | 200 |    9.422271ms |  xxx.xxx.xxx.xxx | POST     "/machine/uuid0/map"
[GIN] 2022/03/19 - 10:30:46 | 200 |        34m44s |  xxx.xxx.xxx.xxx | POST     "/machine/uuid1/map"
panic: send on closed channel

goroutine 134 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x441585, {0x13dbff0, 0xc0004ee000}, _, _, {{0xd6, 0x56, 0xcd, 0x97, 0x3d, ...}}, ...)
	/go/src/headscale/poll.go:596 +0x3ad
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
	/go/src/headscale/poll.go:279 +0x24b 

Same issue here. The last request before the panic took 34 minutes. The machine with uuid1 is suspended every night but the headscale controller (v0.15.0-beta6) has crashed even when the machine is not suspended. I'll keep an eye on my logs and see if any other machines on my tailnet are causing problems.

More logs with trace enabled

2022-03-20T02:58:26Z TRC Creating Map response func=getMapResponse machine=desktop
2022-03-20T02:58:26Z TRC go/src/headscale/machine.go:227 > Finding direct peers machine=desktop
2022-03-20T02:58:26Z TRC go/src/headscale/machine.go:242 > Found peers: [ phone, laptop, server ](3) machine=desktop
2022-03-20T02:58:26Z TRC go/src/headscale/machine.go:279 > Found total peers: [ phone, laptop, server ](3) machine=desktop
2022-03-20T02:58:26Z TRC Generated map response: { Node: desktop.private.my.domain, Peers: [ phone.private.my.domain, laptop.private.my.domain, server.private.my.domain ](3) } func=getMapResponse machine=desktop
2022-03-20T02:58:26Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=desktop
2022-03-20T02:58:26Z TRC Waiting for data to stream... handler=PollNetMapStream machine=desktop
2022-03-20T02:58:26Z TRC pollData is (chan []uint8)(0xc0001eca20), keepAliveChan is (chan []uint8)(0xc00055c8a0), updateChan is (chan struct {})(0xc00055c840) handler=PollNetMapStream machine=desktop
2022-03-20T02:58:31Z ERR Could not write the map response error="write tcp xxx.xxx.xxx.xxx:443->xxx.xxx.xxx.xxx:38520: write: no route to host" channel=update handler=PollNetMapStream machine=phone
2022-03-20T02:58:31Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=f7a82208f435c585411cc3784431130207808b96fd51a893fb02dacd15c39009 machine=phone
2022-03-20T02:58:31Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=phone
2022-03-20T02:58:31Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=phone
2022-03-20T02:58:31Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=phone
[GIN] 2022/03/20 - 02:58:31 | 200 |      2h43m47s |  xxx.xxx.xxx.xxx | POST     "/machine/f7a82208f435c585411cc3784431130207808b96fd51a893fb02dacd15c39009/map"
panic: send on closed channel

goroutine 5576 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x441585, {0x13dbff0, 0xc000280d40}, _, _, {{0xf7, 0xa8, 0x22, 0x8, 0xf4, ...}}, ...)
	/go/src/headscale/poll.go:596 +0x3ad
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
	/go/src/headscale/poll.go:279 +0x24b
@ash0x72 commented on GitHub (Mar 19, 2022): ``` [GIN] 2022/03/19 - 10:30:20 | 200 | 9.422271ms | xxx.xxx.xxx.xxx | POST "/machine/uuid0/map" [GIN] 2022/03/19 - 10:30:46 | 200 | 34m44s | xxx.xxx.xxx.xxx | POST "/machine/uuid1/map" panic: send on closed channel goroutine 134 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x441585, {0x13dbff0, 0xc0004ee000}, _, _, {{0xd6, 0x56, 0xcd, 0x97, 0x3d, ...}}, ...) /go/src/headscale/poll.go:596 +0x3ad created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /go/src/headscale/poll.go:279 +0x24b ``` Same issue here. The last request before the panic took 34 minutes. The machine with uuid1 is suspended every night but the headscale controller (v0.15.0-beta6) has crashed even when the machine is not suspended. I'll keep an eye on my logs and see if any other machines on my tailnet are causing problems. More logs with trace enabled ``` 2022-03-20T02:58:26Z TRC Creating Map response func=getMapResponse machine=desktop 2022-03-20T02:58:26Z TRC go/src/headscale/machine.go:227 > Finding direct peers machine=desktop 2022-03-20T02:58:26Z TRC go/src/headscale/machine.go:242 > Found peers: [ phone, laptop, server ](3) machine=desktop 2022-03-20T02:58:26Z TRC go/src/headscale/machine.go:279 > Found total peers: [ phone, laptop, server ](3) machine=desktop 2022-03-20T02:58:26Z TRC Generated map response: { Node: desktop.private.my.domain, Peers: [ phone.private.my.domain, laptop.private.my.domain, server.private.my.domain ](3) } func=getMapResponse machine=desktop 2022-03-20T02:58:26Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=desktop 2022-03-20T02:58:26Z TRC Waiting for data to stream... handler=PollNetMapStream machine=desktop 2022-03-20T02:58:26Z TRC pollData is (chan []uint8)(0xc0001eca20), keepAliveChan is (chan []uint8)(0xc00055c8a0), updateChan is (chan struct {})(0xc00055c840) handler=PollNetMapStream machine=desktop 2022-03-20T02:58:31Z ERR Could not write the map response error="write tcp xxx.xxx.xxx.xxx:443->xxx.xxx.xxx.xxx:38520: write: no route to host" channel=update handler=PollNetMapStream machine=phone 2022-03-20T02:58:31Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=f7a82208f435c585411cc3784431130207808b96fd51a893fb02dacd15c39009 machine=phone 2022-03-20T02:58:31Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=phone 2022-03-20T02:58:31Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=phone 2022-03-20T02:58:31Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=phone [GIN] 2022/03/20 - 02:58:31 | 200 | 2h43m47s | xxx.xxx.xxx.xxx | POST "/machine/f7a82208f435c585411cc3784431130207808b96fd51a893fb02dacd15c39009/map" panic: send on closed channel goroutine 5576 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x441585, {0x13dbff0, 0xc000280d40}, _, _, {{0xf7, 0xa8, 0x22, 0x8, 0xf4, ...}}, ...) /go/src/headscale/poll.go:596 +0x3ad created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /go/src/headscale/poll.go:279 +0x24b ```
Author
Owner

@gabm commented on GitHub (Mar 29, 2022):

Some more logs from 0.15.0-beta2

2022-03-28T15:50:27Z TRC pollData is (chan []uint8)(0xc00051a600), keepAliveChan is (chan []uint8)(0xc000732120), updateChan is (chan struct {})(0xc0007320c0) handler=PollNetMapStream machine=pc-D
2022-03-28T15:50:28Z DBG Sending update request func=scheduledPollWorker machine=pc-C
2022-03-28T15:50:28Z TRC Received a request for update channel=update handler=PollNetMapStream machine=pc-C
2022-03-28T15:50:28Z TRC Latest times []time.Time{time.Date(2022, time.March, 28, 15, 50, 23, 617760256, time.UTC)}
2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:436 > Checking if pc-C is missing updates last_state_change=1648482618 last_successful_update=1648482623 machine=pc-C
2022-03-28T15:50:28Z TRC Latest times []time.Time{time.Date(2022, time.March, 28, 15, 50, 23, 617760256, time.UTC)}
2022-03-28T15:50:28Z DBG There has been updates since the last successful update to pc-C handler=PollNetMapStream last_state_change=1648482623 last_successful_update=1648482618 machine=pc-C
2022-03-28T15:50:28Z TRC Creating Map response func=getMapResponse machine=pc-C
2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:151 > Finding peers filtered by ACLs machine=pc-C
2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:218 > Found some machines: [pc-A pc-B pc-C pc-D] machine=pc-C
2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:279 > Found total peers: [ pc-A, pc-D ](2) machine=pc-C
2022-03-28T15:50:28Z TRC Generated map response: { Node: pc-C.example.com, Peers: [ pc-A.example.com, pc-D.example.com ](2) } func=getMapResponse machine=pc-C
2022-03-28T15:50:28Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=pc-C
2022-03-28T15:50:28Z TRC Waiting for data to stream... handler=PollNetMapStream machine=pc-C
2022-03-28T15:50:28Z TRC pollData is (chan []uint8)(0xc0001a6540), keepAliveChan is (chan []uint8)(0xc0007cc1e0), updateChan is (chan struct {})(0xc0007cc180) handler=PollNetMapStream machine=pc-C
2022-03-28T15:50:33Z TRC Waiting for data to stream... handler=PollNetMapStream machine=pc-A
2022-03-28T15:50:33Z TRC pollData is (chan []uint8)(0xc000325b00), keepAliveChan is (chan []uint8)(0xc000732300), updateChan is (chan struct {})(0xc0007322a0) handler=PollNetMapStream machine=pc-A
2022-03-28T15:50:33Z INF The client has closed the connection handler=PollNetMapStream machine=pc-A
2022-03-28T15:50:33Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=097ba29eac21818d8c94daef36c7fba23733d54cbc1865437f665442545a6c24 machine=pc-A
2022-03-28T15:50:33Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=pc-A
2022-03-28T15:50:33Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=pc-A
2022-03-28T15:50:33Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=pc-A
panic: send on closed channel

goroutine 82549 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x43f9a5, {0x139aad0, 0xc00009a140}, _, _, {{0x9, 0x7b, 0xa2, 0x9e, 0xac, ...}}, ...)
        /home/runner/work/headscale/headscale/poll.go:585 +0x3ad
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
        /home/runner/work/headscale/headscale/poll.go:268 +0x24b

@gabm commented on GitHub (Mar 29, 2022): Some more logs from 0.15.0-beta2 ``` 2022-03-28T15:50:27Z TRC pollData is (chan []uint8)(0xc00051a600), keepAliveChan is (chan []uint8)(0xc000732120), updateChan is (chan struct {})(0xc0007320c0) handler=PollNetMapStream machine=pc-D 2022-03-28T15:50:28Z DBG Sending update request func=scheduledPollWorker machine=pc-C 2022-03-28T15:50:28Z TRC Received a request for update channel=update handler=PollNetMapStream machine=pc-C 2022-03-28T15:50:28Z TRC Latest times []time.Time{time.Date(2022, time.March, 28, 15, 50, 23, 617760256, time.UTC)} 2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:436 > Checking if pc-C is missing updates last_state_change=1648482618 last_successful_update=1648482623 machine=pc-C 2022-03-28T15:50:28Z TRC Latest times []time.Time{time.Date(2022, time.March, 28, 15, 50, 23, 617760256, time.UTC)} 2022-03-28T15:50:28Z DBG There has been updates since the last successful update to pc-C handler=PollNetMapStream last_state_change=1648482623 last_successful_update=1648482618 machine=pc-C 2022-03-28T15:50:28Z TRC Creating Map response func=getMapResponse machine=pc-C 2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:151 > Finding peers filtered by ACLs machine=pc-C 2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:218 > Found some machines: [pc-A pc-B pc-C pc-D] machine=pc-C 2022-03-28T15:50:28Z TRC ../../../runner/work/headscale/headscale/machine.go:279 > Found total peers: [ pc-A, pc-D ](2) machine=pc-C 2022-03-28T15:50:28Z TRC Generated map response: { Node: pc-C.example.com, Peers: [ pc-A.example.com, pc-D.example.com ](2) } func=getMapResponse machine=pc-C 2022-03-28T15:50:28Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=pc-C 2022-03-28T15:50:28Z TRC Waiting for data to stream... handler=PollNetMapStream machine=pc-C 2022-03-28T15:50:28Z TRC pollData is (chan []uint8)(0xc0001a6540), keepAliveChan is (chan []uint8)(0xc0007cc1e0), updateChan is (chan struct {})(0xc0007cc180) handler=PollNetMapStream machine=pc-C 2022-03-28T15:50:33Z TRC Waiting for data to stream... handler=PollNetMapStream machine=pc-A 2022-03-28T15:50:33Z TRC pollData is (chan []uint8)(0xc000325b00), keepAliveChan is (chan []uint8)(0xc000732300), updateChan is (chan struct {})(0xc0007322a0) handler=PollNetMapStream machine=pc-A 2022-03-28T15:50:33Z INF The client has closed the connection handler=PollNetMapStream machine=pc-A 2022-03-28T15:50:33Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=097ba29eac21818d8c94daef36c7fba23733d54cbc1865437f665442545a6c24 machine=pc-A 2022-03-28T15:50:33Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=pc-A 2022-03-28T15:50:33Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=pc-A 2022-03-28T15:50:33Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=pc-A panic: send on closed channel goroutine 82549 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x43f9a5, {0x139aad0, 0xc00009a140}, _, _, {{0x9, 0x7b, 0xa2, 0x9e, 0xac, ...}}, ...) /home/runner/work/headscale/headscale/poll.go:585 +0x3ad created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /home/runner/work/headscale/headscale/poll.go:268 +0x24b ```
Author
Owner

@Niek commented on GitHub (Mar 31, 2022):

I see the same issue on v0.15.0:

panic: send on closed channel

goroutine 4318 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x442b05?, {0x14119e8, 0xc000418240}, _, _, {{0x30, 0x32, 0xf1, 0x31, 0x9c, ...}}, ...)
        /go/src/headscale/poll.go:596 +0x38d
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
        /go/src/headscale/poll.go:279 +0x232
@Niek commented on GitHub (Mar 31, 2022): I see the same issue on v0.15.0: ``` panic: send on closed channel goroutine 4318 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x442b05?, {0x14119e8, 0xc000418240}, _, _, {{0x30, 0x32, 0xf1, 0x31, 0x9c, ...}}, ...) /go/src/headscale/poll.go:596 +0x38d created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /go/src/headscale/poll.go:279 +0x232 ```
Author
Owner

@gabm commented on GitHub (Apr 4, 2022):

I have another log that has a very important error message I think 2022-03-31T11:14:26Z ERR Could not write the map response error="write tcp AAA.AAA.AAA.AAA:8080->BBB.BBB.BBB.BBB:46572: write: no route to host" channel=update handler=PollNetMapStream machine=pc-A

2022-03-31T11:14:26Z DBG There has been updates since the last successful update to pc-A handler=PollNetMapStream last_state_change=1648725265 last_successful_update=1648724562 machine=pc-A
2022-03-31T11:14:26Z TRC Creating Map response func=getMapResponse machine=pc-A
2022-03-31T11:14:26Z TRC ../../../runner/work/headscale/headscale/machine.go:151 > Finding peers filtered by ACLs machine=pc-A
2022-03-31T11:14:26Z TRC ../../../runner/work/headscale/headscale/machine.go:218 > Found some machines: [pc-A pc-B pc-C pc-D] machine=pc-A
2022-03-31T11:14:26Z TRC ../../../runner/work/headscale/headscale/machine.go:279 > Found total peers: [ pc-B, pc-C, pc-D ](3) machine=pc-A
2022-03-31T11:14:26Z TRC Generated map response: { Node: pc-A.gabm.example.com, Peers: [ pc-B.gabm2.example.com, pc-C.servers.example.com, pc-D.servers.example.com ](3) } func=getMapResponse machine=pc-A
2022-03-31T11:14:26Z ERR Could not write the map response error="write tcp AAA.AAA.AAA.AAA:8080->BBB.BBB.BBB.BBB:46572: write: no route to host" channel=update handler=PollNetMapStream machine=pc-A
2022-03-31T11:14:26Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=097ba29eac21818d8c94daef36c7fba23733d54cbc1865437f665442545a6c24 machine=pc-A
2022-03-31T11:14:26Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=pc-A
2022-03-31T11:14:26Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=pc-A
2022-03-31T11:14:26Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=pc-A
@gabm commented on GitHub (Apr 4, 2022): I have another log that has a very important error message I think `2022-03-31T11:14:26Z ERR Could not write the map response error="write tcp AAA.AAA.AAA.AAA:8080->BBB.BBB.BBB.BBB:46572: write: no route to host" channel=update handler=PollNetMapStream machine=pc-A` ``` 2022-03-31T11:14:26Z DBG There has been updates since the last successful update to pc-A handler=PollNetMapStream last_state_change=1648725265 last_successful_update=1648724562 machine=pc-A 2022-03-31T11:14:26Z TRC Creating Map response func=getMapResponse machine=pc-A 2022-03-31T11:14:26Z TRC ../../../runner/work/headscale/headscale/machine.go:151 > Finding peers filtered by ACLs machine=pc-A 2022-03-31T11:14:26Z TRC ../../../runner/work/headscale/headscale/machine.go:218 > Found some machines: [pc-A pc-B pc-C pc-D] machine=pc-A 2022-03-31T11:14:26Z TRC ../../../runner/work/headscale/headscale/machine.go:279 > Found total peers: [ pc-B, pc-C, pc-D ](3) machine=pc-A 2022-03-31T11:14:26Z TRC Generated map response: { Node: pc-A.gabm.example.com, Peers: [ pc-B.gabm2.example.com, pc-C.servers.example.com, pc-D.servers.example.com ](3) } func=getMapResponse machine=pc-A 2022-03-31T11:14:26Z ERR Could not write the map response error="write tcp AAA.AAA.AAA.AAA:8080->BBB.BBB.BBB.BBB:46572: write: no route to host" channel=update handler=PollNetMapStream machine=pc-A 2022-03-31T11:14:26Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=097ba29eac21818d8c94daef36c7fba23733d54cbc1865437f665442545a6c24 machine=pc-A 2022-03-31T11:14:26Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=pc-A 2022-03-31T11:14:26Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=pc-A 2022-03-31T11:14:26Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=pc-A ```
Author
Owner

@victorhooi commented on GitHub (Apr 7, 2022):

I'm getting these regularly as well - this is on 0.15.0:

2022-04-06T12:26:31Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro-2
2022-04-06T12:26:31Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro-2
2022-04-06T12:26:31Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro-2
2022-04-06T12:38:16Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro
2022-04-06T12:38:16Z ERR Cannot decode message error="cannot decrypt response" handler=PollNetMap
[GIN] 2022/04/06 - 12:38:16 | 400 |         530µs |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
[GIN] 2022/04/06 - 12:38:16 | 200 |        12m38s |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T12:38:16Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:38:16Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:38:16Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:39:16Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro
[GIN] 2022/04/06 - 12:39:16 | 200 | 59.935147185s |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T12:39:16Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:39:16Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:39:16Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:59:28Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro
[GIN] 2022/04/06 - 12:59:28 | 200 |        20m12s |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T12:59:28Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:59:28Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro
2022-04-06T12:59:28Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:00:31Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro
[GIN] 2022/04/06 - 13:00:31 | 200 |          1m2s |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T13:00:31Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:00:31Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:00:31Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:02:37Z INF Client sent endpoint update and is ok with a response without peer list handler=PollNetMap machine=victors-macbook-pro
[GIN] 2022/04/06 - 13:02:37 | 200 |    5.523529ms |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T13:04:44Z ERR Cannot decode message error="cannot decrypt response" handler=PollNetMap
[GIN] 2022/04/06 - 13:04:44 | 400 |      113.04µs |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T13:04:44Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro
[GIN] 2022/04/06 - 13:04:44 | 200 |         4m12s |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
2022-04-06T13:04:44Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:04:44Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:04:44Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro
2022-04-06T13:09:31Z INF unary dur=0.46181 md={":authority":"/var/run/headscale.sock","content-type":"application/grpc","user-agent":"grpc-go/1.44.1-dev"} method=ListMachines req={} service=headscale.v1.HeadscaleService
2022-04-06T13:19:35Z INF Client sent endpoint update and is ok with a response without peer list handler=PollNetMap machine=victors-macbook-pro
[GIN] 2022/04/06 - 13:19:35 | 200 |     5.73467ms |   116.255.30.16 | POST     "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map"
[GIN] 2022/04/06 - 13:35:32 | 200 |        1h9m0s |   116.255.30.16 | POST     "/machine/376fcfb58e559ef1badbf298c6328443cade66ec1ab2f088bf87b5a646e4013c/map"
panic: send on closed channel

goroutine 174 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x780d16?, {0x140ac70, 0xc0003ac4c0}, _, _, {{0x37, 0x6f, 0xcf, 0xb5, 0x8e, ...}}, ...)
        /home/runner/work/headscale/headscale/poll.go:596 +0x38d
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
        /home/runner/work/headscale/headscale/poll.go:279 +0x232

I've just edited /etc/headscale/config.yaml to set log_level: trace, I'll see if the issue recurs.

@victorhooi commented on GitHub (Apr 7, 2022): I'm getting these regularly as well - this is on 0.15.0: ``` 2022-04-06T12:26:31Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro-2 2022-04-06T12:26:31Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro-2 2022-04-06T12:26:31Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro-2 2022-04-06T12:38:16Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro 2022-04-06T12:38:16Z ERR Cannot decode message error="cannot decrypt response" handler=PollNetMap [GIN] 2022/04/06 - 12:38:16 | 400 | 530µs | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" [GIN] 2022/04/06 - 12:38:16 | 200 | 12m38s | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T12:38:16Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:38:16Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:38:16Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:39:16Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro [GIN] 2022/04/06 - 12:39:16 | 200 | 59.935147185s | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T12:39:16Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:39:16Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:39:16Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:59:28Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro [GIN] 2022/04/06 - 12:59:28 | 200 | 20m12s | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T12:59:28Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:59:28Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro 2022-04-06T12:59:28Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:00:31Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro [GIN] 2022/04/06 - 13:00:31 | 200 | 1m2s | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T13:00:31Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:00:31Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:00:31Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:02:37Z INF Client sent endpoint update and is ok with a response without peer list handler=PollNetMap machine=victors-macbook-pro [GIN] 2022/04/06 - 13:02:37 | 200 | 5.523529ms | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T13:04:44Z ERR Cannot decode message error="cannot decrypt response" handler=PollNetMap [GIN] 2022/04/06 - 13:04:44 | 400 | 113.04µs | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T13:04:44Z INF The client has closed the connection handler=PollNetMapStream machine=victors-macbook-pro [GIN] 2022/04/06 - 13:04:44 | 200 | 4m12s | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" 2022-04-06T13:04:44Z INF Client is ready to access the tailnet handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:04:44Z INF Sending initial map handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:04:44Z INF Notifying peers handler=PollNetMap machine=victors-macbook-pro 2022-04-06T13:09:31Z INF unary dur=0.46181 md={":authority":"/var/run/headscale.sock","content-type":"application/grpc","user-agent":"grpc-go/1.44.1-dev"} method=ListMachines req={} service=headscale.v1.HeadscaleService 2022-04-06T13:19:35Z INF Client sent endpoint update and is ok with a response without peer list handler=PollNetMap machine=victors-macbook-pro [GIN] 2022/04/06 - 13:19:35 | 200 | 5.73467ms | 116.255.30.16 | POST "/machine/904651de9cdf76c9634cf78d71dc4cb0b04ce088edb328d26c046231234d4705/map" [GIN] 2022/04/06 - 13:35:32 | 200 | 1h9m0s | 116.255.30.16 | POST "/machine/376fcfb58e559ef1badbf298c6328443cade66ec1ab2f088bf87b5a646e4013c/map" panic: send on closed channel goroutine 174 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0x780d16?, {0x140ac70, 0xc0003ac4c0}, _, _, {{0x37, 0x6f, 0xcf, 0xb5, 0x8e, ...}}, ...) /home/runner/work/headscale/headscale/poll.go:596 +0x38d created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /home/runner/work/headscale/headscale/poll.go:279 +0x232 ``` I've just edited `/etc/headscale/config.yaml` to set `log_level: trace`, I'll see if the issue recurs.
Author
Owner

@victorhooi commented on GitHub (Apr 7, 2022):

It just crashed on me - but the messages look slightly different, but perhaps that's because of trace?

2022-04-07T02:58:37Z TRC Generated map response: { Node: victors-macbook-pro.victorhooi.example.com, Peers: [ victors-macbook-pro-2.victorhooi.example.com ](1) } func=getMapResponse machine=Victors-MacBook-Pro
2022-04-07T02:58:37Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=victors-macbook-pro
2022-04-07T02:58:37Z TRC Waiting for data to stream... handler=PollNetMapStream machine=victors-macbook-pro
2022-04-07T02:58:37Z TRC pollData is (chan []uint8)(0xc00046fc20), keepAliveChan is (chan []uint8)(0xc0000947e0), updateChan is (chan struct {})(0xc000094780) handler=PollNetMapStream machine=victors-macbook-pro
2022-04-07T02:58:45Z ERR Could not write the map response error="write tcp 10.152.15.194:8080->116.255.30.16:59950: write: connection timed out" channel=update handler=PollNetMapStream machine=victors-macbook-pro-2
2022-04-07T02:58:45Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=044ff1aa25be45fb7b8d59b6c0cf8fdc266625bb9637ca9fb0eb257f698f721d machine=victors-macbook-pro-2
2022-04-07T02:58:45Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=victors-macbook-pro-2
2022-04-07T02:58:45Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=victors-macbook-pro-2
2022-04-07T02:58:45Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=victors-macbook-pro-2
[GIN] 2022/04/07 - 02:58:45 | 200 |        18m52s |   116.255.30.16 | POST     "/machine/044ff1aa25be45fb7b8d59b6c0cf8fdc266625bb9637ca9fb0eb257f698f721d/map"
panic: send on closed channel

goroutine 26147 [running]:
github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0xc0005a9fd0?, {0x140ac70, 0xc00079d880}, _, _, {{0x4, 0x4f, 0xf1, 0xaa, 0x25, ...}}, ...)
        /home/runner/work/headscale/headscale/poll.go:596 +0x38d
created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
        /home/runner/work/headscale/headscale/poll.go:279 +0x232
@victorhooi commented on GitHub (Apr 7, 2022): It just crashed on me - but the messages look slightly different, but perhaps that's because of trace? ``` 2022-04-07T02:58:37Z TRC Generated map response: { Node: victors-macbook-pro.victorhooi.example.com, Peers: [ victors-macbook-pro-2.victorhooi.example.com ](1) } func=getMapResponse machine=Victors-MacBook-Pro 2022-04-07T02:58:37Z TRC Updated Map has been sent channel=update handler=PollNetMapStream machine=victors-macbook-pro 2022-04-07T02:58:37Z TRC Waiting for data to stream... handler=PollNetMapStream machine=victors-macbook-pro 2022-04-07T02:58:37Z TRC pollData is (chan []uint8)(0xc00046fc20), keepAliveChan is (chan []uint8)(0xc0000947e0), updateChan is (chan struct {})(0xc000094780) handler=PollNetMapStream machine=victors-macbook-pro 2022-04-07T02:58:45Z ERR Could not write the map response error="write tcp 10.152.15.194:8080->116.255.30.16:59950: write: connection timed out" channel=update handler=PollNetMapStream machine=victors-macbook-pro-2 2022-04-07T02:58:45Z TRC Finished stream, closing PollNetMap session handler=PollNetMap id=044ff1aa25be45fb7b8d59b6c0cf8fdc266625bb9637ca9fb0eb257f698f721d machine=victors-macbook-pro-2 2022-04-07T02:58:45Z TRC Closing keepAliveChan channel channel=Done handler=PollNetMap machine=victors-macbook-pro-2 2022-04-07T02:58:45Z TRC Closing pollDataChan channel channel=Done handler=PollNetMap machine=victors-macbook-pro-2 2022-04-07T02:58:45Z TRC Closing updateChan channel channel=Done handler=PollNetMap machine=victors-macbook-pro-2 [GIN] 2022/04/07 - 02:58:45 | 200 | 18m52s | 116.255.30.16 | POST "/machine/044ff1aa25be45fb7b8d59b6c0cf8fdc266625bb9637ca9fb0eb257f698f721d/map" panic: send on closed channel goroutine 26147 [running]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0xc0005a9fd0?, {0x140ac70, 0xc00079d880}, _, _, {{0x4, 0x4f, 0xf1, 0xaa, 0x25, ...}}, ...) /home/runner/work/headscale/headscale/poll.go:596 +0x38d created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream /home/runner/work/headscale/headscale/poll.go:279 +0x232 ```
Author
Owner

@reynico commented on GitHub (Apr 8, 2022):

Same here,

Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: panic: send on closed channel
Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: goroutine 116 [running]:
Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0xc000728060, {0x13dbff0, 0xc000717f00
}, _, _, {{0xa4, 0x43, 0xb5, 0xcb, 0x84, ...}}, ...)
Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]:         /tmp/headscale/poll.go:596 +0x3ad
Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream
Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]:         /tmp/headscale/poll.go:279 +0x24b

For me, it's pretty much transparent because I'm running Headscale on a Systemd unit with Restart=always but I'd love to fix it.

@reynico commented on GitHub (Apr 8, 2022): Same here, ``` Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: panic: send on closed channel Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: goroutine 116 [running]: Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: github.com/juanfont/headscale.(*Headscale).scheduledPollWorker(0xc000728060, {0x13dbff0, 0xc000717f00 }, _, _, {{0xa4, 0x43, 0xb5, 0xcb, 0x84, ...}}, ...) Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: /tmp/headscale/poll.go:596 +0x3ad Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: created by github.com/juanfont/headscale.(*Headscale).PollNetMapStream Apr 08 14:39:22 ip-10-10-11-7 headscale[136744]: /tmp/headscale/poll.go:279 +0x24b ``` For me, it's pretty much transparent because I'm running Headscale on a Systemd unit with `Restart=always` but I'd love to fix it.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: starred/headscale#131