Polling resources get forever stuck after a network disconnect

[danielpodwysocki]

When I create a resource that is poll-based, I see that if it hits an issue hitting the API it relies on, it later doesn't keep reconciling it.

I observed it first with some API errors on the providers end, but I could soon reproduce by turning turning my network adapter on/off.

I suspect a context isn't passing a timeout somewhere, but I didn't get to dig into the code to find whether it's an issue with the resource or polling itself.

Reproduction:

1. Create 3 hetzner VMs such as:

		hetzner:vm "${name}" {
			apitoken => $provider_configs["hetzner"]["hz_token"],
			state => $state,
			allowrebuild => "ifneeded",
			servertype => $size_map["hetzner"][$size],
			datacenter => "fsn1-dc14",
			image => $provider_configs["hetzner"]["default_image"],
			userdata => $provider_configs["hetzner"]["cloud_init_data"],
			waitinterval => 1,
			waittimeout => 15, # this is intentionally low, I turned it down just to observe what happens.  I normally use 300
			Meta:poll => 10,
		}

2. Start mgmt
3. Delete one VM just to observe it come in 10 seconds (correct/expected)
4. Disable your network adapter, wait 20 seconds
5. Re-enable your network adapter
6. Now delete a VM and wait. It will never come back. (incorrect/I'd expect mgmt to be able to recover)

Tested on latest main branch, built my binary off of 17082d012f60dd2e7839476690227e83310f0ecf

[danielpodwysocki]

Ah, wait, that is not latest master - will retest quickly to confirm it's still affected.

[danielpodwysocki]

Yup, getting the same on b47273b14b95022952ed4075d26a1b8461c31420 .

The logs just stop:

20:58:28 engine: hetzner:vm[hello]: polling...
20:58:28 engine: hetzner:vm[hello3]: polling...
20:58:28 engine: hetzner:vm[hello2]: polling...
20:58:38 engine: hetzner:vm[hello2]: polling...
20:58:48 engine: hetzner:vm[hello2]: polling...

# nothing ever shows up here

[danielpodwysocki]

Oh, very interesting - I was going to ctrl+c before I go to sleep, but mgmt just hung and never exited. I had to pass SIGKILL to make it stop.

[purpleidea]

Thank you for reporting this. Try with only one vm please. And if it hangs, then please press ^\ see: https://purpleidea.com/blog/2016/02/15/debugging-golang-programs/ and paste the full trace somewhere. Please make sure you're on git master too.

It is possible that is an issue with the specific resource not handling a context... When we find those, we should absolutely fix them. I don't see anything overly obvious in the hetzner code, but I also didn't write it. It could also do with a bump in the library, so if you want to go get -u the deps for it, I am happy to merge those changes.

Lastly there could in theory be a deadlock in the engine related to polling or another bug, but if so, we'd find it with a trace I think. I actually have a pending "be extra extra careful to not deadlock" patch queued, but I think it's not even required. I should hopefully merge it anyways this month.

Thank you for playing with all this!

[purpleidea]

Here is that branch if you want to test it. I haven't test it at all yet.

https://github.com/purpleidea/mgmt/tree/feat/more-context-changes

[danielpodwysocki]

Got the same repro on more-context-changes.

With one vm only, still on more-context-changes, here's a coredump:

coredump.txt

so if you want to go get -u the deps for it, I am happy to merge those changes

Will do in a spare moment and re-test everything works (outside/regardless the bug here) - I see there's a v2, but all the methods used in the resource seem compatible at a glance.

[danielpodwysocki]

(I hit send too fast on this message, just getting the master coredump now :D )

[danielpodwysocki]

Here it is: dump-master.txt

[purpleidea]

I've made a branch with the hetzner deps bumped:

https://github.com/purpleidea/mgmt/tree/feat/bump-hetzner

If you're interested in trying that, lmk if you can repro there before I dig too deeply into the trace.

[purpleidea]

I would also need the full exact mcl code (you can remove a password string and replace it with "hunter2" in your paste) and the full cli of how you ran it.

If you test on: https://github.com/purpleidea/mgmt/tree/feat/bump-hetzner that's preferred just to avoid me tracking down a hetzer bug that's already been fixed ;)

[danielpodwysocki]

Sidenote/another thing I've observed:

Couple times upon initial machine creation I got:

18:38:14 engine: hetzner:vm[hello]: Error: error during Process(): checkApplyServerState failed: waitUntil(serverInSteadyState) exited early: timeout: exit condition not confirmed after 15 seconds

I only got that once when creating a fresh machine, not when it already exists - if it exists, we go into polling correctly, so I assume we're just hitting some slowness on Hetzner's end.
I have added Meta:retry => -1 to the resource, but that did not get it to reconcile again - should it?

[danielpodwysocki]

Reproed the issue on the branch with bumped hetzner.

My MCL:

import "os"
import "golang/strings" as golang_strings

$hz_token_filepath = "/home/daniel/localsecrets/apitoken.txt"
$hz_token = golang_strings.trim_space(os.readfile($hz_token_filepath))

hetzner:vm "hello" {
	apitoken => $hz_token,
	state => "running",
	servertype => "cx33",
	datacenter => "fsn1-dc14",
	image => "fedora-43",
	waitinterval => 1,
	waittimeout => 15,
	Meta:poll => 10,
}

And coredump:
coredump-bumped-hetzner.txt

What is interesting is once I get it into this state, I can do mgmt deploy for example and no new resources will show up,even if i add them to the deployed mcl.
So it's not a problem with just that resource, it blocks mgmt as a whole.

[purpleidea]

Perfect, thanks. And exactly what cli command do you use to run this mcl please?

[danielpodwysocki]

I've ran it with: ./mgmt run --tmp-prefix lang simple-repro.mcl

[purpleidea]

In this trace:

goroutine 150 gp=0xc00059a380 m=nil [select, 1 minutes]:
runtime.gopark(0xc00063ff70?, 0x2?, 0x40?, 0xfd?, 0xc00063feac?)
	runtime/proc.go:460 +0xce fp=0xc00063fd00 sp=0xc00063fce0 pc=0x488a6e
runtime.selectgo(0xc00063ff70, 0xc00063fea8, 0x1?, 0x0, 0x0?, 0x1)
	runtime/select.go:351 +0x9d7 fp=0xc00063fe70 sp=0xc00063fd00 pc=0x463f97
github.com/purpleidea/mgmt/cli.(*RunArgs).Run.func3()
	github.com/purpleidea/mgmt/cli/run.go:197 +0x275 fp=0xc00063ffe0 sp=0xc00063fe70 pc=0x2da2455
runtime.goexit({})
	runtime/asm_amd64.s:1693 +0x1 fp=0xc00063ffe8 sp=0xc00063ffe0 pc=0x4918e1
created by github.com/purpleidea/mgmt/cli.(*RunArgs).Run in goroutine 1
	github.com/purpleidea/mgmt/cli/run.go:188 +0x17ed

It's not clear that you pressed ^C ...

Did you??

[danielpodwysocki]

No, I pressed ctrl + \ and then it exited on its own.

[danielpodwysocki]

Here's one where i pressed ctrl+c -> it was hanging -> then I coredumped:

Used latest master for the build, ba67e2d64281022dc4248b14c63a58bc4cae66cc

mgmt-ctrlc-coredump.txt

[purpleidea]

Okay, good news, bad news!

After digging through the trace, here is the offending part:

goroutine 189 gp=0xc000c2e8c0 m=nil [select]:
runtime.gopark(0xc0010efbd0?, 0x4?, 0x20?, 0xf9?, 0xc0010efa8c?)
	runtime/proc.go:460 +0xce fp=0xc0010ef8e0 sp=0xc0010ef8c0 pc=0x488a6e
runtime.selectgo(0xc0010efbd0, 0xc0010efa84, 0x3a071fc?, 0x0, 0x7c0381c10200?, 0x1)
	runtime/select.go:351 +0x9d7 fp=0xc0010efa50 sp=0xc0010ef8e0 pc=0x463f97
net/http.(*http2ClientConn).roundTrip(0xc000d49880, 0xc00086e640, 0x0)
	net/http/h2_bundle.go:8680 +0xb2c fp=0xc0010efd58 sp=0xc0010efa50 pc=0x9b7bcc
net/http.(*http2ClientConn).RoundTrip(...)
	net/http/h2_bundle.go:8595
net/http.(*http2Transport).RoundTripOpt(0xc0003a9d60, 0xc00086e640, {0x74?, 0x0?})
	net/http/h2_bundle.go:7921 +0x385 fp=0xc0010efef8 sp=0xc0010efd58 pc=0x9b0c45
net/http.(*http2Transport).RoundTrip(...)
	net/http/h2_bundle.go:7872
net/http.http2noDialH2RoundTripper.RoundTrip({0x57c6500?}, 0xc00086e640)
	net/http/h2_bundle.go:10475 +0x3a fp=0xc0010eff50 sp=0xc0010efef8 pc=0x9c8b7a
net/http.(*Transport).roundTrip(0x57c6500, 0xc00086e640)
	net/http/transport.go:615 +0x617 fp=0xc0010f01e8 sp=0xc0010eff50 pc=0xa12d17
net/http.(*Transport).RoundTrip(0x57c6500, 0xc00086e640)
	net/http/roundtrip.go:33 +0x39 fp=0xc0010f0220 sp=0xc0010f01e8 pc=0xa2e019
net/http.send(0xc00086e640, {0x4149c40, 0x57c6500}, {0x8?, 0x8?, 0x0?})
	net/http/client.go:259 +0x8cb fp=0xc0010f04b0 sp=0xc0010f0220 pc=0x968a8b
net/http.(*Client).send(0xc000d1fd70, 0xc00086e640, {0x0?, 0x492fd9?, 0x0?})
	net/http/client.go:180 +0x14d fp=0xc0010f0568 sp=0xc0010f04b0 pc=0x967f2d
net/http.(*Client).do(0xc000d1fd70, 0xc00086e640)
	net/http/client.go:729 +0x13b9 fp=0xc0010f0878 sp=0xc0010f0568 pc=0x96bcf9
net/http.(*Client).Do(...)
	net/http/client.go:587
github.com/hetznercloud/hcloud-go/hcloud.(*Client).Do(0xc000830c00, 0xc00086e640, {0x327f060, 0xc0009158f0})
	github.com/hetznercloud/hcloud-go@v1.59.2/hcloud/client.go:264 +0x37e fp=0xc0010f0a00 sp=0xc0010f0878 pc=0x267e0fe
github.com/hetznercloud/hcloud-go/hcloud.(*ServerClient).List(0xc000830d18, {0x416a1e0, 0xc0005265f0}, {{0x0, 0x0, {0x0, 0x0}}, {0xc0009c7007, 0x5}, {0x0, ...}, ...})
	github.com/hetznercloud/hcloud-go@v1.59.2/hcloud/server.go:271 +0x18c fp=0xc0010f1020 sp=0xc0010f0a00 pc=0x26c5eac
github.com/hetznercloud/hcloud-go/hcloud.(*ServerClient).GetByName(0xc000830d18, {0x416a1e0, 0xc0005265f0}, {0xc0009c7007, 0x5})
	github.com/hetznercloud/hcloud-go@v1.59.2/hcloud/server.go:221 +0xf0 fp=0xc0010f1130 sp=0xc0010f1020 pc=0x26c5610
github.com/purpleidea/mgmt/engine/resources.(*HetznerVMRes).getServerUpdate(0xc0004e6248, {0x416a1e0, 0xc0005265f0})
	github.com/purpleidea/mgmt/engine/resources/hetzner_vm.go:613 +0x145 fp=0xc0010f11b8 sp=0xc0010f1130 pc=0x2a16d65
github.com/purpleidea/mgmt/engine/resources.(*HetznerVMRes).CheckApply(0xc0004e6248, {0x416a1e0, 0xc0005265f0}, 0x1)
	github.com/purpleidea/mgmt/engine/resources/hetzner_vm.go:406 +0x65 fp=0xc0010f1258 sp=0xc0010f11b8 pc=0x2a15885
github.com/purpleidea/mgmt/engine/graph.safeCheckApply({0x416a1e0, 0xc0005265f0}, {0x4187b08, 0xc0004e6248}, 0x1)
	github.com/purpleidea/mgmt/engine/graph/actions.go:835 +0xf8 fp=0xc0010f12f8 sp=0xc0010f1258 pc=0x18feb18
github.com/purpleidea/mgmt/engine/graph.(*Engine).Process(0xc000a42000, {0x416a1e0, 0xc0005265f0}, {0x7c03383b10f0, 0xc0004e6248})
	github.com/purpleidea/mgmt/engine/graph/actions.go:300 +0x1412 fp=0xc0010f18e8 sp=0xc0010f12f8 pc=0x18f7372
github.com/purpleidea/mgmt/engine/graph.(*Engine).Worker(0xc000a42000, {0x7c03383b10f0, 0xc0004e6248})
	github.com/purpleidea/mgmt/engine/graph/actions.go:769 +0x1ba5 fp=0xc0010f1e50 sp=0xc0010f18e8 pc=0x18fc1e5
github.com/purpleidea/mgmt/engine/graph.(*Engine).Commit.func1.2.1({0x7c03383b10f0, 0xc0004e6248})
	github.com/purpleidea/mgmt/engine/graph/engine.go:310 +0x2a7 fp=0xc0010f1fa8 sp=0xc0010f1e50 pc=0x1904207
github.com/purpleidea/mgmt/engine/graph.(*Engine).Commit.func1.2.gowrap1()
	github.com/purpleidea/mgmt/engine/graph/engine.go:323 +0x50 fp=0xc0010f1fe0 sp=0xc0010f1fa8 pc=0x1903f30
runtime.goexit({})
	runtime/asm_amd64.s:1693 +0x1 fp=0xc0010f1fe8 sp=0xc0010f1fe0 pc=0x4918e1
created by github.com/purpleidea/mgmt/engine/graph.(*Engine).Commit.func1.2 in goroutine 188
	github.com/purpleidea/mgmt/engine/graph/engine.go:295 +0x209

The bad part is here:

github.com/hetznercloud/hcloud-go/hcloud.(*Client).Do(0xc000830c00, 0xc00086e640, {0x327f060, 0xc0009158f0})
	github.com/hetznercloud/hcloud-go@v1.59.2/hcloud/client.go:264 +0x37e fp=0xc0010f0a00 sp=0xc0010f0878 pc=0x267e0fe
github.com/hetznercloud/hcloud-go/hcloud.(*ServerClient).List(0xc000830d18, {0x416a1e0, 0xc0005265f0}, {{0x0, 0x0, {0x0, 0x0}}, {0xc0009c7007, 0x5}, {0x0, ...}, ...})
	github.com/hetznercloud/hcloud-go@v1.59.2/hcloud/server.go:271 +0x18c fp=0xc0010f1020 sp=0xc0010f0a00 pc=0x26c5eac
github.com/hetznercloud/hcloud-go/hcloud.(*ServerClient).GetByName(0xc000830d18, {0x416a1e0, 0xc0005265f0}, {0xc0009c7007, 0x5})
	github.com/hetznercloud/hcloud-go@v1.59.2/hcloud/server.go:221 +0xf0 fp=0xc0010f1130 sp=0xc0010f1020 pc=0x26c5610
github.com/purpleidea/mgmt/engine/resources.(*HetznerVMRes).getServerUpdate(0xc0004e6248, {0x416a1e0, 0xc0005265f0})
	github.com/purpleidea/mgmt/engine/resources/hetzner_vm.go:613 +0x145 fp=0xc0010f11b8 sp=0xc0010f1130 pc=0x2a16d65

So a bug in hetzner that's not listening to the ctx ... I assume, I didn't dig into it... I started but then I noticed:

 * [new tag]         v1.58.0                         -> v1.58.0
 * [new tag]         v1.59.0                         -> v1.59.0
 * [new tag]         v1.59.1                         -> v1.59.1
 * [new tag]         v1.59.2                         -> v1.59.2
 * [new tag]         v2.0.0                          -> v2.0.0
 * [new tag]         v2.1.0                          -> v2.1.0
 * [new tag]         v2.1.1                          -> v2.1.1
...

It turns out when I bumped to the latest version, I didn't realize it was the latest 1.x version :/

I've now patched this in: https://github.com/purpleidea/mgmt/tree/feat/hetzner-v2

If it passes the tests I'll merge, but do please test and let me know if that fixes the issue. If not, when you press ^C if it doesn't shutdown, do another trace and I'll read it again.

Thanks for your patience and for your very helpful reporting.

[purpleidea]

(NOTE: this is merged in git master now.)