Making systemd StartTransientUnit synchronous (mini post-mortem on that)

Opening an issue here so we can try to understand the sequence to events, the current situation and what to do next.

cc @derekwaynecarr @vikaschoudhary16 @sjenning @mrunalp

1. The original behavior of libcontainer systemd cgroup driver was to send systemd the StartTransientUnit request via D-Bus, but not wait for a reply.
2. This caused a race condition, in that it's possible that runc/libcontainer would create the directories using os.MkdirAll (which creates the directories, if they don't exist.)
3. systemd (at least v219, version in RHEL 7) will decide which controllers get created (which might not be the whole set) and will remove controllers that weren't supposed to exist.
4. Due to this race, a controller directory might get created by runc/libcontainer, while later be removed by systemd (still in the process of creating the cgroups for the scope.)
5. In order to fix this issue, PR #1683 attempted to make StartTransientUnit synchronous, so that the whole creation of the scope/slice by systemd is completed before runc/libcontainer does any cgroup processing.
   a. I believe this approach is appropriate. Waiting for the operation to complete before proceeding is the correct behavior here.
   b. The problem with PR #1683 was that the StartTransientUnit call breaks on errors only when err != nil && !isUnitExists(err), so in the case where the unit already exists, blocking on the channel is a mistake, since there's no pending operation from systemd. (Personal note: this would have been unlikely to have happened on a language with proper exception handling.)
6. The bug introduced in step 5(b) started causing trouble in kubelet (Kubernetes), since it does call libcontainer on the same cgroup multiple times, and the latter calls will trigger the isUnitExists(err) situation that will make the libcontainer code now block on a channel that will never receive any message. So kubelet startup gets stuck there. (BTW, I spent a couple days trying to troubleshoot that myself too, seeing kubelet mysteriously fail to initialize when using systemd cgroup driver.)
7. To address that bug, PR #1754 introduced a timeout on blocking on the channel. If an answer was not received within one second, we would stop waiting on the channel.
   a. A timeout is probably appropriate, blocking forever is really not good. I'm not sure one second is long enough for a timeout. I also think the action of assuming everything went well in this case is also not necessarily appropriate. Perhaps this can be done better here, maybe retry the call (which should be idempotent, since creating the same unit multiple times will actually get into the isUnitExists case we've discussed previously.)
   b. This PR also introduced a bug. Since now, if the timeout occurs, then no one is ever reading from that channel again, which means later on when the job completes, the code writing to it will block, forever.
8. I found the bug in 5(b) and pushed PR #1772 to fix it. In doing so, I kept the code adding the timeout, in step 7, after all according to 7(a), having a timeout is definitely not inappropriate. At the time, I didn't realize bug 7(b) existed, so I didn't address it.
9. Trying to backport these into Kubernetes code base, in PR kubernetes/kubernetes#61926, @derekwaynecarr raised what I believe is the bug in 7(b) (since he added references to startJob(), jobComplete() and the jobListener lock in coreos/go-systemd/dbus.)
   a. I think we need to address the actual bug in 7(b).
10. In that same discussion, @vikaschoudhary16 suggests that the version of systemd in RHEL 7 has been "fixed", I assume that's referring to the behavior described in (3). I imagine this was a backport from an upstream patch on that behavior.
    a. I'd appreciate to know more details about this, including which upstream patch has been used to fix this behavior.
    b. Regardless of the change in behavior in systemd, I still think the intent of the PR in (5) was correct, the call to StartTransientUnit should be blocking and even if it's benign, we should avoid any race between systemd and runc/libcontainer manipulating the cgroup tree.
11. @sjenning suggests reverting all the three PRs (here, in libcontainer), since according to (10), the issue introduced by the race condition no longer exists, so we could revert back to the original behavior.
    a. Once again, I don't think that's appropriate, since even if it's benign, a race condition is still there and could come back to bite us in the future. Having the "create cgroup" operation be synchronous is the appropriate behavior here. In any other situation, where we're creating a resource and then consuming a resource, I'm sure we would have wanted the same.
    b. Rather than reverting everything, I think we should address the bug in 7(b) and fix it.
12. Small note on a circumstance that makes the bug even worse... The code that's writing on the channel (and is getting blocked when the bug in 7(b) triggers) is within a critical section where a lock is being held. That means every other operation that involves that lock will also get stuck.
    a. I think that's a bug too, and should be addressed.

My proposals here are that, instead of rolling back, we fix the actual bugs that still exist here. I still assert that keeping the synchronous behavior of StartTransientUnit is the proper approach.

Regarding the potential fixes (or workarounds) for 7(b):

• We could create the channel using statusChan := make(chan string, 1) which buffers one write to this channel. That way, the write to the channel will not block, even if we stopped listening on it due to a timeout. This is very localized and doesn't really have bad side effects, even when timeouts occur. We could also increase the timeout from 1s to something a bit higher. I think this would probably be a good start.
• We should probably address the locking in coreos/go-systemd/dbus, moving the write to the channel to outside the lock. (There's no harm in doing that outside the lock.) We might further consider doing that write from a go-routine, so if it blocks we don't really get stuck. (The downside there is that we risk leaking go-routines in this situation.)
• We could consider extending the API of coreos/go-systemd/dbus to add the ability to cancel a blocking channel, in case of a timeout, so no write is done when not needed. But this looks like it might be quite intrusive to add, has some races of its own that have to be dealt with, so not sure whether it's actually worth it...
• We could consider doing some kind of retry logic in case of timeout. Simply assuming the operation succeeded in that case looks really wrong... We could consider adding timeout/retry logic to coreos/go-systemd/dbus instead of here. (Not really sure, need to investigate.) We probably don't need that right away, but long term, it's something we should probably consider.

I think that's all for now... I hope this describes the situation fairly accurately, otherwise please leave comments (we can come back and edit the description to fix anything if there are mistakes.)

Cheers,
Filipe

Start with libcontainer/cgroups/systemd/apply_systemd.go, especially the StartTransientUnit flow and its channel handling, then read coreos/go-systemd/dbus/methods.go around startJob(), jobComplete(), and the jobListener lock. Review PRs #1683, #1754, and #1772 alongside the post-mortem to understand the competing fixes. Done requires an agreed resolution for timeout, channel, and locking behavior rather than simply reverting the synchronous operation.