FIX: fix the bud -> when check pod pending delete it, main process blocked && format project

[calmkart]

for issue #436
fix the main process blocked bug.

The following are the detailed triggering reasons

• if the watch for khcheck cr any change, we'll k.RestartChecks()
  https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/cmd/kuberhealthy/kuberhealthy.go#L183-L199

• but in k.StopChecks() it will wait for c.Shutdown()
  https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/cmd/kuberhealthy/kuberhealthy.go#L115-L140

• int c.Shutdown(),trigger ext.shutdownCTXFunc() , and wait for ext.wg.Wait()
  https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L1216-L1240

• if we run a check, the func (ext *Checker) RunOnce() error {} it will waitForPodStart
  https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L619-L631

• the ext.waitForPodStart will run ext.wg.Add(1)
  https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L938-L1015

but ,in the waitForPodStart() function, if the pod deleted before p.Status.Phase == apiv1.PodRunning || p.Status.Phase == apiv1.PodFailed || p.Status.Phase == apiv1.PodSucceeded, the for e := range watcher.ResultChan() for loop will blocked.

so the k.StopChecks() will blocked, the k.RestartChecks() will blocked.
https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/cmd/kuberhealthy/kuberhealthy.go#L183-L199

we can watch for delete pod event here and return err.

I also saw a method func (ext *Checker) watchForCheckerPodShutdown(shutdownEventNotifyC chan struct{}, ctx context.Context)
https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L597-L599
https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L374-L415
https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L460-L500

but the func (ext *Checker) waitForDeletedEvent(eventsIn <-chan watch.Event, sawRemovalChan chan struct{}, stoppedChan chan struct{}) do nothing.
https://github.com/Comcast/kuberhealthy/blob/3309e2b740e635f00bcd257c5ba0be5209ddaed2/pkg/checks/external/main.go#L469-L494

if a check pod create, it's status will be pending first, and the waitForDeletedEvent will return if it's status be 'pending', because it's a watch.Modified, the case watch.Deleted: never run. Because we can't delete a pod before it pending.

I haven't carefully observed whether this method has any other effect, so I didn't modify the logic here, or left it as it is. Just in waitForPodStart() watch for the delete event.

[calmkart]

@jonnydawg
PTAL, thanks.
This bug bothers me so much, I worked for it all day.

[joshulyne]

@calmkart seems like we can't reproduce the bug? I tried applying this deployment configuration https://github.com/Comcast/kuberhealthy/blob/master/deploy/kuberhealthy.yaml and as soon as the deployment check comes up as pending, I delete the deployment checker pod and I see a lot of this in the kuberhealthy logs:

time="2020-04-24T18:37:20Z" level=info msg="4246412f-1e52-433a-889b-49d8b9b672cb kuberhealthy/deployment: [waiting for external checker pod to report in...]"
time="2020-04-24T18:37:20Z" level=info msg="4246412f-1e52-433a-889b-49d8b9b672cb kuberhealthy/deployment: [Last report time was: 0001-01-01 00:00:00 +0000 UTC vs 0001-01-01 00:00:00 +0000 UTC]"
time="2020-04-24T18:37:20Z" level=info msg="4246412f-1e52-433a-889b-49d8b9b672cb kuberhealthy/deployment: [have not yet seen pod update since 0001-01-01 00:00:00 +0000 UTC]"

Which is expected since it can't find the checker pod that was deleted. However, once the check hits its timeout interval, another check gets provisioned and completes successfully. Have you tried waiting until the timeout interval instead of the run interval for the check to run again? Also, let me know if there's something else I'm missing in order to reproduce this!

[jonnydawg]

I'm not sure if I'm able to reproduce this bug yet -- still checking it out. I'm getting a lot of

time="2020-04-24T18:12:23Z" level=info msg="dfaf914c-f3f7-4f90-b6a6-b8f53abbee53 kuberhealthy/deployment: [pod state is now: Pending]"
time="2020-04-24T18:12:23Z" level=info msg="dfaf914c-f3f7-4f90-b6a6-b8f53abbee53 kuberhealthy/deployment: [got an event while waiting for pod to start running]"
time="2020-04-24T18:12:23Z" level=info msg="dfaf914c-f3f7-4f90-b6a6-b8f53abbee53 kuberhealthy/deployment: [pod state is now: Pending]"
time="2020-04-24T18:12:29Z" level=debug msg="Starting a watch for khcheck object changes"
time="2020-04-24T18:12:30Z" level=debug msg="khcheck monitor saw an added event"
time="2020-04-24T18:12:30Z" level=debug msg="Change notification received. Scanning for external check changes..."
time="2020-04-24T18:12:30Z" level=debug msg="Scanning khcheck CRD kuberhealthy/deployment for changes since last seen..."
time="2020-04-24T18:13:10Z" level=info msg="khState reaper: starting to run an audit"
time="2020-04-24T18:13:10Z" level=info msg="khState reaper: analyzing 1 khState resources"
time="2020-04-24T18:13:10Z" level=debug msg="khState reaper: analyzing khState deployment in deployment"
time="2020-04-24T18:13:10Z" level=debug msg="khState reaper: deployment == deployment && kuberhealthy == kuberhealthy"
time="2020-04-24T18:13:10Z" level=info msg="khState reaper: deployment in kuberhealthy is still valid"
time="2020-04-24T18:14:10Z" level=info msg="khState reaper: starting to run an audit"
time="2020-04-24T18:14:10Z" level=info msg="khState reaper: analyzing 1 khState resources"
time="2020-04-24T18:14:10Z" level=debug msg="khState reaper: analyzing khState deployment in deployment"
time="2020-04-24T18:14:10Z" level=debug msg="khState reaper: deployment == deployment && kuberhealthy == kuberhealthy"

[calmkart]

how to trigger this bug

video

This log is very important

Waiting for background workers to cleanup...

but never get shutdown

https://github.com/Comcast/kuberhealthy/blob/0e4d57a10cefed3e816f630197afaca0178b219a/pkg/checks/external/main.go#L1216-L1240

the reason why ext.wg.Wait() blocked was Already written on the main post.

@joshulyne @jonnydawg

[jonnydawg]

I've been able to reproduce the bug, thanks for the video! I've also been testing your changes and they look good so far -- I'm going to continue some testing for a bit.

[jonnydawg]

Looks good! Thanks for doing this!

[integrii]

Thank you @calmkart - this looks great! I appreciate the fix and thorough explanation of the issue. This could have gone on awhile and been hard to track down but you nailed it quickly.