Swarmkit: Agent Segfaults in Logs Calls

[dperny]

💀 💀 💀 abandon all hope ye who enter here 💀 💀 💀

Here's a doozy. Filing here so we can record and retain discussion.

@vdemeester has reported to me that he can semi-regularly reproduce SIGSEGV by creating a service and accessing the logs almost instantly in some cases. The exact cause is likely not directly related to some change logs introduced, but is more likely the consequence of a data race.

The docker log output of the crash is this:

[signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x105dbe4]

goroutine 372 [running]:
panic(0x17cb5e0, 0xc420012060)
        /usr/local/go/src/runtime/panic.go:500 +0x1a1
github.com/docker/docker/vendor/github.com/docker/swarmkit/agent.(*taskManager).Logs(0x0, 0x7f05c05cb0a8, 0xc42131d560, 0xc42128fcb8, 0x2, 0x2, 0x1, 0x0, 0x0, 0x2612aa0, ...)
        /go/src/github.com/docker/docker/vendor/github.com/docker/swarmkit/agent/task.go:68 +0xa4
created by github.com/docker/docker/vendor/github.com/docker/swarmkit/agent.(*worker).Subscribe
        /go/src/github.com/docker/docker/vendor/github.com/docker/swarmkit/agent/worker.go:572 +0x54c
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x105dbe4]

goroutine 371 [running]:
panic(0x17cb5e0, 0xc420012060)
        /usr/local/go/src/runtime/panic.go:500 +0x1a1
github.com/docker/docker/vendor/github.com/docker/swarmkit/agent.(*taskManager).Logs(0x0, 0x7f05c05cb0a8, 0xc4212e1f20, 0xc42128fd50, 0x2, 0x2, 0x1, 0x0, 0x0, 0x2612aa0, ...)
        /go/src/github.com/docker/docker/vendor/github.com/docker/swarmkit/agent/task.go:68 +0xa4
created by github.com/docker/docker/vendor/github.com/docker/swarmkit/agent.(*worker).Subscribe
        /go/src/github.com/docker/docker/vendor/github.com/docker/swarmkit/agent/worker.go:572 +0x54c

The reproduction of this is kind of complicated to explain and involves code in a private repo, but the logs of our discussion about it are available on request. Suffice to say, roughly what is occurring is a logs are being called immediately after a service is created by some tool, but the segfault seems to only occur in a laptop environment. Basically all of the hallmarks of an obscure race condition. I invite @vdemeester to share any other information he has.

The gist of the problem is at this point in the worker we are calling the Logs method on the taskmanager value, which is nil.[1] That's causing this access to the nil object in the task manager to segfault.

For some reason I believe it is the case that a task is getting created, which is making it into the event queue, and then is being destroyed before the logs can be started. The simple fix is a nil check but I am strongly concerned that introducing a nil check simply hides some other deficiency or error or race in the code that this segfault is revealing by chance

What I Need:

I really need someone else who understands this part of the code to confirm for me that a nil check will suffice, and this segfault is _not_ the result of some deeper deficiency or structural error. If someone can confirm for me that a nil-check suffices, I can make and submit that PR.

@stevvooe I hereby summon you from The Great Beyond (whatever project you're working on now) to hopefully give me some help here. Also @aaronlehmann.

[1] For reasons sure to induce eldritch madness in mortals should they choose to investigate them, Go will let you call methods on nil objects. I am Not Particularly Partial™ to this design decision.

[dperny]

tl;dr: Task is being created and put into an event channel, but no corresponding task manager with that ID exists in the map in the worker of all task managers when we do a lookup. Calling logs on this nonexistent taskmanager, for obvious reasons, fails horribly.

[stevvooe]

There are two issues:

1. I think the panic is caused by https://github.com/docker/swarmkit/blob/f807c19f9f16183139c05e291d6a8632dd625df2/agent/worker.go#L429. We post an event for a new task manager creation without checking whether or not that will be successful. The event should only be publish once the task is fully created.
2. At https://github.com/docker/swarmkit/blob/f807c19f9f16183139c05e291d6a8632dd625df2/agent/worker.go#L461, exec.Resolve leaks an error, causing the task manager startup to fail. That error should really land on the task's status and be reported as a rejection. Looks like there could be a problem with early validation of the mounts (thought I stamped that out) or exec.Resolve is treating something as fatal that isn't.
3. Stop validating mounts when resolving the controller. https://github.com/moby/moby/blob/master/daemon/cluster/executor/container/container.go#L63. That is not the right place to report the error; do it late and it will be handled where it matters. newController should only report errors for things that can resolve a runtime.

Hope that helps!

[nathanleclaire]

@dperny In case you didn't know, you can compile go binaries with the -race flag that turns on automatic race detection. Then there will be big ugly error messages spit out when a race is detected in the resulting binary. I'd consider starting with fixing all of those in your dupe if you haven't tried that yet.

(Note: It's possible the race detector will fail to show races that do exist, but IIRC it never shows false positives. So if something shows up there it's _definitely_ a for realsies race.)

[dperny]

@nathanleclaire Part of the problem is I don't have a working duplication. It's only on @vdemeester's laptop.

[nathanleclaire]

I'm a bit curious why https://github.com/docker/swarmkit/blob/f807c19f9f16183139c05e291d6a8632dd625df2/agent/worker.go#L571-L573 wraps the action in a mutex, but then goes off and spawns a goroutine to do it.

There's nothing blocking in the critical section. That strikes me as really odd. @aluzzardi Any idea what's up with that?

[stevvooe]

@dperny Added a third item. I'll send a PR to swarmkit that addresses 1 and 2.

[stevvooe]

@nathanleclaire @vdemeester probably has some "poison" in the task store that has an old, invalid task with misconfigured bind mounts. These errors are leaking out of resolution (correctish, in this case) and that causes the publish to the taskevents queue for a task manager that was never created.

Anywho, PR incoming.

[stevvooe]

Related to #1542.

[dperny]

Applying P0 because this is a literal segfault and we should rightly block release if it doesn't get fixed cc @aluzzardi

[aaronlehmann]

@nathanleclaire: It's for the map read.

[vdemeester]

@nathanleclaire @vdemeester probably has some "poison" in the task store that has an old, invalid task with misconfigured bind mounts. These errors are leaking out of resolution (correctish, in this case) and that causes the publish to the taskevents queue for a task manager that was never created.

@stevvooe interesting. I remember having an invalid task with misconfigured bind mounts but it's been a while and the service was removed (maybe it was still poisonning the thing but it would be a little bit weird.

[nathanleclaire]

Gotcha. FWIW, might want to consider wrapping the map/locks in a struct like the pattern described here (with Get/Set methods that do the locking).