Failed health checks still deploy

[helgi]

From @sstarcher on May 3, 2016 17:19

I created an app that without proper configuration would fail health checks. The following steps were followed.

• Deis create app
• git push deis
• First version of app is deployed and in a crashback loop as expected
• deis config:set HEALTHCHECK_URL=/
• Second app version deployed and in a crashback loop as expected. At this point kubectl get rcs --namespace=app shows 2 app versions are in a crashback loop
• deis config:set rest of data to make app function
• Third app version claims it has passed the health check, but the app takes several minutes to start up. At this point the deis router routes to the app and gives a 503 even though the deis command line shows the app is good. deis info shows version 3 of the app is up
• Third version of the app finally comes up after several minutes and the router routes correctly to the app.
• deis config:set is used to break the application configuration.
• Fourth version of the app comes up and deis believes it has passed the health check. Deis removes the third version of the app and now the router is back to a 503.

End result is

NAME                 READY     STATUS             RESTARTS   AGE
hound-v1-cmd-2fe47   0/1       CrashLoopBackOff   20         1h
hound-v2-cmd-qggwg   0/1       Error              5          33m
hound-v4-cmd-dw6u6   0/1       CrashLoopBackOff   6          9m

Old RCs are still hanging around and the app is down due to the third version being deleted prior to the 4th version passing health checks.

deis config:list

HEALTHCHECK_FAILURE_THRESHOLD      3
HEALTHCHECK_INITIAL_DELAY          1080
HEALTHCHECK_PERIOD_SECONDS         10
HEALTHCHECK_PORT                   5000
HEALTHCHECK_SUCCESS_THRESHOLD      1
HEALTHCHECK_TIMEOUT                400
HEALTHCHECK_URL                    /

Copied from original issue: deis/workflow#214

[helgi]

As it stand right now Deis has various timeouts when it is checking the kubernetes API and seeing if the pods are up and running. This is roughly ~2 mins timeout or so...

However Deis is not stopping the deploy if you see a situation like you are describing, it could end in a scenario where you have your old RC deleted. There is a failsafe switch that is supposed to rather bring up the old RC (up to previous scale) and kill off the new RC; seems like that is not kicking in for you.

One thing to take note of is the high initial delay and high timeout - We account for neither right now in our timeout handling for deploy / scale operations

[sstarcher]

@helgi thank you for the additional info. I have now seen in several different occasions a healthy running app being updated with an app that never passes the health check and the old healthy RC is deleted which takes down the app.

[sstarcher]

Is it intended going forward that git push deis can succeed, but the application is never put live? I don't believe that was the case in Deis v1.

Going forward will users need to query Deis to verify the new release succeeded?

[helgi]

@sstarcher I believe there may be a bug in the builder that is showing you success when it should be a failure.

The intent is not to have people verify these by hand, my point in the previous comment was more to list out what we may not be accounting for yet and could be making Deis return earlier, and do additional actions. Such as our cleanup procedure might be kicking in and killing v3 for you.

The way deploy works is that we bring in 1 pod of the new app, and remove 1 pod of the old (which we also did in v1; v2 does try to do more than 1 in/out if it has capacity if you are using current master and you can set DEIS_DEPLOY_BATCHES to 4 if you want 4 in/out kind of deployment) - With that model we will bring in the pod and query k8s on various status checks (including the health check), however we generally only have a 2 minute timeout on that operation.

Now if you consider the 2 minute timeout and then start looking at the fact you have a 1080 second INITIAL_DELAY (18 minute delay) then kubernetes won't even start consider to check the health of the app (readiness nor liveness) until after 18 minutes. During that time the pod should not be attached to the Service (in kubernetes) and thus not routable

If you have more than 1 pod then this will compound and deploy of the pods will take quite a wile, at least for kubernetes to funnel it into active usage

http://kubernetes.io/docs/user-guide/pod-states/ may help understand things beyond my ramblings :)
This is the key thing:

The default state of Readiness before the initial delay is Failure

Right now Deis combines your healthcheck into a readiness and a liveness check

It would help if you could put the controller log into a gist and link here for one of your deploys so I can see what's happening so we can come up with a plan of action.

Hope this sheds a bit of light, let me know if you need more info on a particular piece

[sstarcher]

I removed the 10.245.188.1 "GET /healthz HTTP/1.1" 200 2 "Go 1.1 package http" from the other applications. v10 was the functional application that got scaled out of existence. v11 had it's config changed to ensure it would fail the health check.

INFO app-latest: config app-latest-739613e updated
INFO app-latest: release app-latest-v11 created
INFO [app-latest]: jenkins changed HEALTHCHECK_URL
DEBUG create app-latest
DEBUG deploy app-latest-v11-cmd, img app-latest:git-7940f64b, params {'envs': {'HEALTHCHECK_PERIOD_SECONDS': 10, 'HEALTHCHECK_TIMEOUT': 120, 'HEALTHCHECK_FAILURE_THRESHOLD': 10, 'HEALTHCHECK_PORT': 8080, 'deis_whitelist': '10.0.0.0/16', 'HEALTHCHECK_URL': '/servlet/noooo', 'HEALTHCHECK_SUCCESS_THRESHOLD': 1, 'HEALTHCHECK_INITIAL_DELAY': 60, 'profile': 'aws-us-east-1-production-web'}, 'version': 'v11', 'healthcheck': {'timeout': 120, 'path': '/servlet/noooo', 'success_threshold': 1, 'period_seconds': 10, 'failure_threshold': 10, 'delay': 60, 'port': 8080}, 'batches': None, 'app_type': 'cmd', 'build_type': 'dockerfile', 'cpu': {}, 'replicas': 1, 'tags': {}, 'memory': {}, 'routable': True}, cmd ""
DEBUG scaling release app-latest-v11-cmd to 1 out of final 1
DEBUG waiting for 1 pods in app-latest namespace to be in services (120s timeout)
DEBUG waited 10s and 0 pods are in service
DEBUG waited 20s and 0 pods are in service
DEBUG waited 30s and 0 pods are in service
DEBUG waited 40s and 0 pods are in service
DEBUG waited 50s and 0 pods are in service
DEBUG waited 60s and 0 pods are in service
DEBUG waited 70s and 0 pods are in service
DEBUG waited 80s and 0 pods are in service
DEBUG waited 90s and 0 pods are in service
DEBUG waited 100s and 0 pods are in service
DEBUG waited 110s and 0 pods are in service
DEBUG 0 out of 1 pods in namespace app-latest are in service
DEBUG scaling old release app-latest-v10-cmd from original 1 to 0
DEBUG scaling RC app-latest-v10-cmd in Namespace app-latest from 1 to 0 replicas
DEBUG waiting for RC app-latest-v10-cmd to get a newer resource version than 94307274 (30s timeout)
DEBUG RC app-latest-v10-cmd has a new resource version 95173194
DEBUG waiting for 1 pods in app-latest namespace to be terminated (30s timeout)
DEBUG waited 10s and 0 pods out of 1 are fully terminated
DEBUG waited 20s and 0 pods out of 1 are fully terminated
DEBUG 1 pods in namespace app-latest are terminated
DEBUG Not scaling RC app-latest-v10-cmd in Namespace app-latest to 0 replicas. Already at desired replicas

[helgi]

Thanks - You are being bitten by the (somewhat arbitrary) 120 second timeout which never passes but we then happily go ahead start scaling down old release.

This one is a bit of a tough cookie... On one hand we should bail out if pods are not coming up within X period but on the other hand it is often k8s taking extra long and the deploy will eventually finish. If we bailed out then you'd never be able to finish (as things stand).

I'm going to think about this for a bit and see if I can come up with a solution that accounts for all these variances - Be warned tho, your deploy can take considerably longer if I start adding in more checks and balances (but you could cheat that by being generous with DEIS_DEPLOY_BATCHES or have many nodes)

If you are willing to fork the controller for now and bump up the timeouts then you can modify this line https://github.com/deis/controller/blob/master/rootfs/scheduler/__init__.py#L858 to be a much higher value, to fit your needs - You may run into this: #652 if you do a very high value but that's only a maybe.

[sstarcher]

@helgi I'm in no hurry as I won't be using this in production until after Deis v2 is stable. Let me know if you need me to test anything out. We do have 2 separate apps that take a while to load. One takes 60-90s and the other one can take upward of 5mins as it has to warm a very large cache before being healthy.

[helgi]

Is that large cache warmed up on every deploy (as in local to every pod) or just the first time you put it on deis?

How acceptable to you is a very slow deploy, given the warmup period of your applications? Only so fast we can go, the main downside we have is the lack of feedback from the API back into the CLI, or just lack of feedback in generally from the API.

[sstarcher]

@helgi the things that takes a very long time would be on every deploy, but it's perfectly fine for it to also take a very long time to update. It's an internal tool and very rarely has any changes applied to it. If we had two instance of it and it takes them 5 mins to become healthy it would be no problem for it to take 10-20mins for all the applications to roll.

[helgi]

@sstarcher #709 partially addresses this - It basically takes your initial delay and combines it with the normal timeout (120s)

That way each pod gets a longer "wait" time while k8s and the health checkers are doing their thing.

See if you can give it a spin and if it addresses some of your issues

[sstarcher]

I likely won't get a chance to test it out until next week.

[sstarcher]

I once again reproduce this problem running rc1. The deis controller took my app out of service when the new app was never healthy.