Router liveness probe failures

[brenton]

I hate filing issues like this (ie we don't yet know exactly how to reproduce the problem) but @sosiouxme, @sdodson, @thoraxe and I have hit an edge case where the router liveness check will fail which results in a tight loop of "destroy the router / launch the router".

Right now we mostly want to raise awareness of this problem to see if anyone is hitting it upstream. The code we're testing with is rarely ever more than a half a day old or so. I'm fairly certain we're dealing with an odd edge case. Any advice for debugging the problem the next time we see it would be appreciated. For starters:

• How is the default router port 80 tcp liveness probe run? Does it run from the Master or the Node?
• What ip does it hit? (I'm assuming it's using the published endpoints but I'm not sure where it's being run from).

[brenton]

After working for almost an hour my router just went in to the liveness probe failure loop. After several minutes of looping it came back.

[sdodson]

I put in a bit of instrumentation.

glog.V(3).Infof("TCPSocket Probe PodIP: %s, Port: %s, Timeout: %s", status.PodIP, port, timeout)

And this is what I get

Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.874785    1343 kubelet.go:1224] Found infra pod for "router-1-u4dra_default"
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.874810    1343 kubelet.go:2059] Returning cached status for "router-1-u4dra_default"
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.874976    1343 kubelet.go:1239] pod "router-1-u4dra_default" container "router" exists as 98a40eac5adb339520993d42fbeb998356571cea8fcc9646b2c28af28603f7a0
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.875017    1343 probe.go:133] TCPSocket Probe PodIP: 10.1.0.2, Port: %!s(int=80), Timeout: 1s
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.875400    1343 probe.go:133] TCPSocket Probe PodIP: 10.1.0.2, Port: %!s(int=80), Timeout: 1s
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.876031    1343 probe.go:133] TCPSocket Probe PodIP: 10.1.0.2, Port: %!s(int=80), Timeout: 1s
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.876202    1343 probe.go:51] Liveness probe unsuccessful: failure
Mar 30 16:26:37 ose3-master.example.com openshift[1343]: I0330 16:26:37.876251    1343 kubelet.go:1257] pod "router-1-u4dra_default" container "router" is unhealthy (probe result: failure). Container will be killed and re-created.

[smarterclayton]

Probes are always run from the node. I would increase the timeout.

[sdodson]

I don't think the timeout is relevant here as it's not waiting a second for the socket, it fires off the three checks in just 1ms based on the output above so the port must be closed. There doesn't seem to be any sleep time between checks which is probably a problem too but I think something else is going on here. Yesterday we tried setting initialDelaySeconds=10 and, at least in my testing, this did not improve the situation.

@pweil- relevant to your interests

[smarterclayton]

What's really interesting is I can think of no good reason for that check to fail. The router should be reusing sockets, which means this is a true failure of the router somewhere. Three checks right after each other also sound wrong but we'll need to run that down upstream.

On Apr 1, 2015, at 10:49 AM, Scott Dodson notifications@github.com wrote:

I don't think the timeout is relevant here as it's not waiting a second for the socket, it fires off the three checks in just 1ms based on the output above so the port must be closed. There doesn't seem to be any sleep time between checks which is probably a problem too but I think something else is going on here. Yesterday we tried setting initialDelaySeconds=10 and, at least in my testing, this did not improve the situation.

@pweil- relevant to your interests

—
Reply to this email directly or view it on GitHub.

[jimmidyson]

I'm seeing this on a clean 0.4.2 install. Anything I can add to help diagnose?

[pweil-]

The last significant change to the router was the reaper which is started by the command. I don't think it is the cause but to rule it out, if you can reproduce this can you try commenting out https://github.com/openshift/origin/blob/master/pkg/cmd/infra/router/router.go#L86 and see what happens?

[jimmidyson]

@pweil- no that didn't help... updated code, rebuilt image, copied over to server having the problem & still couldn't start router.

This works fine on my laptop, just not on the cleanly built server I'm running.

Any more ideas?

[pweil-]

Anything at all in the router logs? I don't think the verbose logging is on by default in the image, you may want to add --loglevel=4 to the image you rebuilt to see if it gives any more clues.

One other thing that may be worth trying is to create the container, allow it to start coming up and then kill openshift to see if you can diagnose the issue before k8s starts killing and restarting things.

Or creating the container manually to see if there are any issues. The easiest way to do that is to get the env that the ex router command would use and plop it into a plain old pod definition. So openshift ex router --create -o json --credentials="$KUBECONFIG", copy and paste into https://gist.github.com/pweil-/3bd200f9ad17e77543df and osc create -f <your file>. That will bring a router up without the probe so you can check it out

[jimmidyson]

Now I've gone back to it the router seems to have started now & running fine... there are about 350 terminated containers before this one started successfully though!

[jimmidyson]

Even with loglevel 4 the container terminates with no log output

[pweil-]

hrm, well that is frustrating :-\

[jimmidyson]

Thing is that the container that started did so with same image as those 350 previous failures so must be something timing wise

[pweil-]

My next debugging step would be to eliminate the probe from the ex command in case there is a bug there somewhere. If the router is really the issue it shouldn't come back up magically unless there is an issue with how config is loaded that works on the 350th try (unless you took a different action in between 349 & 350 like making a service or route)

[jimmidyson]

Wondering if the health check which is think just tcp connects port 80 is just happening too quickly while container is coming up?

OK I'll get rid of health check & see if it works.