Kubernetes pod changes misapplied causing 503 #5901
Labels
area/provider/k8s
kind/bug/possible
a possible bug that needs analysis before it is confirmed or fixed.
status/5-frozen-due-to-age
Projects
Milestone
Comments
mpl
added
kind/bug/possible
|
Hello @zaphod42 , just checking if I got everything right on your configuration and expected behavior.
delay=0s tells k8s to start checking just after the container started, you might get some readiness failures here if your process doesn't start instantly.
In this command you wait 11s before setting it to healthy again and this might not be enough to make the container appear as 'not ready' under k8s according to the previous described readiness probe. Could you share the logs from your pods during those events? And |
|
@ddtmachado, the point it will catch the unready pod isn't quite the product of those two numbers. With those settings, it will be caught between 10 and 12 seconds after having gone ill. For example:
As you can see from that example, 11 seconds is enough to have k8s catch the unready pod with the described settings.
The app doesn't have any logs as it does nothing other than this. I modified our reproduction commands to include $ date; kubectl -n experiment get pods; kubectl -n experiment describe service healthtest-blue-app; kubectl -n experiment exec healthtest-blue-app-666c58b64b-hrxpp -- curl -s -XPOST http://localhost:8000/api/health/ill; sleep 11; kubectl -n experiment exec healthtest-blue-app-666c58b64b-hrxpp -- curl -s -XPOST http://localhost:8000/api/health/healthy; sleep 2; date; kubectl -n experiment get pods; kubectl -n experiment describe service healthtest-blue-app;
Mon 2 Dec 2019 12:50:40 GMT
NAME READY STATUS RESTARTS AGE
healthtest-blue-app-666c58b64b-hrxpp 1/1 Running 0 2d20h
healthtest-blue-ing-7b898f6d7d-tmckz 1/1 Running 0 2d20h
host-sflow-hxrd7 1/1 Running 0 19d
host-sflow-scv2g 1/1 Running 0 19d
host-sflow-xtmkv 1/1 Running 0 19d
refapp-blue-app-6bbdb46b45-mjrj9 1/1 Running 0 5h46m
refapp-blue-app-6bbdb46b45-ms4bd 0/1 Evicted 0 6d19h
refapp-blue-app-6bbdb46b45-zx24p 1/1 Running 0 6d19h
secure-file-senderapp-k8s-blue-app-5c54b6fcfb-29fss 1/1 Running 0 11d
secure-file-senderapp-k8s-blue-app-5c54b6fcfb-drw5l 1/1 Running 0 11d
Name: healthtest-blue-app
Namespace: experiment
Labels: app.kubernetes.io/component=app_service
app.kubernetes.io/instance=blue
app.kubernetes.io/managed-by=stacks
app.kubernetes.io/part-of=healthtest
group=blue
machineset=healthtest
stack=health_test
Annotations: kubectl.kubernetes.io/last-applied-configuration:
{"apiVersion":"v1","kind":"Service","metadata":{"annotations":{},"labels":{"app.kubernetes.io/component":"app_service","app.kubernetes.io/...
Selector: app.kubernetes.io/component=app_service,group=blue,machineset=healthtest,participation=enabled
Type: ClusterIP
IP: 10.50.240.241
Port: app 8000/TCP
TargetPort: 8000/TCP
Endpoints: 10.10.196.37:8000
Session Affinity: None
Events: <none>
Successfully went illSuccessfully went healthyMon 2 Dec 2019 12:50:55 GMT
NAME READY STATUS RESTARTS AGE
healthtest-blue-app-666c58b64b-hrxpp 1/1 Running 0 2d20h
healthtest-blue-ing-7b898f6d7d-tmckz 1/1 Running 0 2d20h
host-sflow-hxrd7 1/1 Running 0 19d
host-sflow-scv2g 1/1 Running 0 19d
host-sflow-xtmkv 1/1 Running 0 19d
refapp-blue-app-6bbdb46b45-mjrj9 1/1 Running 0 5h47m
refapp-blue-app-6bbdb46b45-ms4bd 0/1 Evicted 0 6d19h
refapp-blue-app-6bbdb46b45-zx24p 1/1 Running 0 6d19h
secure-file-senderapp-k8s-blue-app-5c54b6fcfb-29fss 1/1 Running 0 11d
secure-file-senderapp-k8s-blue-app-5c54b6fcfb-drw5l 1/1 Running 0 11d
Name: healthtest-blue-app
Namespace: experiment
Labels: app.kubernetes.io/component=app_service
app.kubernetes.io/instance=blue
app.kubernetes.io/managed-by=stacks
app.kubernetes.io/part-of=healthtest
group=blue
machineset=healthtest
stack=health_test
Annotations: kubectl.kubernetes.io/last-applied-configuration:
{"apiVersion":"v1","kind":"Service","metadata":{"annotations":{},"labels":{"app.kubernetes.io/component":"app_service","app.kubernetes.io/...
Selector: app.kubernetes.io/component=app_service,group=blue,machineset=healthtest,participation=enabled
Type: ClusterIP
IP: 10.50.240.241
Port: app 8000/TCP
TargetPort: 8000/TCP
Endpoints: 10.10.196.37:8000
Session Affinity: None
Events: <none>The output of querying the pod through the ingress Traefik log from that time period |
|
@zaphod42 ok but what you described is the best case scenario and that your script, k8s, your backend and Traefik are all instant reacting to changes to validate it. In reality I can only expect an intermittent behavior on this, exactly as you described on the issue:
Another thing to note is that during the period between a successful probe and a failed one you will always get 503 responses from that pod, and looks like that in the logs as you get 503 for less then 2 seconds, but correct me if I'm wrong as I'm not sure it's the full logs. Besides that I think this is still a bug possible if it is not returning to normal without a restart or another status update on the pod. |
Yes, the problem doesn't always trigger. However it triggers often enough that I can reproduce it after a small number (fewer than 5) of retries of the script that I provided. I also see it happen in our kubernetes cluster running our actual applications (thankfully the cluster is still in a testing phase) around once a day. Those reproductions of the issue come from normal deployments of the application triggered by our CI systems. We fix it right now with
I'm not certain which logs you are referring to. The most recent logs I provided show traefik issuing a 503 response from 12:50:55 until 12:51:06, which is 11 seconds. It cuts off at that point because I stopped making requests. I can provide provide longer logs if you would like. We've seen it remain in this state for around 45 minutes. In that case what appeared to bring it back to normal behaviour was one of the pods changing readiness state again.
If you look at the bottom of my original report, you'll see that I supplied a log of the actions traefik was taking along with an interpretation of those actions. From those logs it appears that traefik contains a race condition of some sort when it applies changes from kubernetes. Is my interpretation of those log lines correct? Does it say that traefik is skipping a configuration change from kubernetes? |
|
Looking through the code it appears that the code to skip some configuration updates is causing the problem. https://github.com/containous/traefik/blob/424e2a9439f8f3b00d7f9f19ed1df3b6d3c8c570/pkg/server/configurationwatcher.go#L172 Here is what I believe is happening:
At this point traefik has discarded the correct configuration and will now remain on configuration B until kubernetes sends another update. |
zaphod42
pushed a commit
to tim-group/stackbuilder
that referenced
this issue
Dec 5, 2019
This uses a traefik that has been patched locally to address traefik/traefik#5901. We should only run this until upstream has released a fix.
2 tasks
|
I don't think this code is the problem, it's comparing traefik CRD config, which would not be the cause of missing updates on service endpoint liveness. Also while throttling can cause skipping, it's only used if you set it explicitly in the configuration. The default value for it will be zero which makes no throttling at all. I gave it a go but could not reproduce the issue. My setup was very similar to yours as I had a simple service that only returned the http status code, manipulated by a url parameter so I could switch between Kubernetes cluster is v1.14.4 Basic manifest: apiVersion: v1
kind: Service
metadata:
name: hc
spec:
ports:
- protocol: TCP
name: hc
port: 80
targetPort: 8080
selector:
app: hc
---
kind: Deployment
apiVersion: extensions/v1beta1
metadata:
name: hc
labels:
app: hc
spec:
replicas: 3
selector:
matchLabels:
app: hc
template:
metadata:
labels:
app: hc
spec:
containers:
- name: healthcheck
image: hc-validator
imagePullPolicy: IfNotPresent
ports:
- name: hc
containerPort: 8080
livenessProbe:
httpGet:
path: /health
port: 8080
---
apiVersion: traefik.containo.us/v1alpha1
kind: IngressRoute
metadata:
name: hcrouter
spec:
entryPoints:
- web
routes:
- match: Host(`hc`)
kind: Rule
services:
- name: hc
port: 80Every time I changed the return code to I may give a go with Kubernetes 1.16.2 later, to see if anything changes, and update here. |
I think we might not be talking about the same thing. The code that I pointed to is on the path of Traefik getting configuration (what the endpoints are that it should be routing to) from the various providers. Do I have that right? To clarify this a bit more, it isn't that Traefik isn't getting the update, it is that it gets the update (we can see that in the logs I provided) but then throws it away. That means that it continues running with an incorrect configuration. I believe that liveness could trigger this as well, but I was reporting seeing this with a readiness check and that is what my reproduction instructions are based on. A liveness check is used by kubernetes to determine if it should delete the container and start it again. Whereas a readiness check is used by kubernetes to deteremine if it should send requests to the container or not. You need to change your Deployment to use a I also noticed that you are using an IngressRoute. We are not using that in our cluster. Instead we have a Deployment that sets up Traefik. You can see it here (as well as how the rest of the wiring that happens around our application deployment: https://github.com/tim-group/stackbuilder/blob/master/lib/stackbuilder/stacks/services/app_service.rb#L988 In the PR I submitted against master (#5952) I have a test case showing the mistake happening at the unit level. If you take that PR, keep the test, and revert the change to I am now running the backported change (submitted as #5954) in my cluster and the issue has not happened again since. I was also unable to reproduce the error using the reproduction steps given above against that patched version.
You can try, but I don't think this issue is specific to kubernetes or any particular version of kubernetes. |
|
I missed one other thing you had in your reproduction case. You set To summarise the setup:
|
|
@zaphod42 Got it, you are right on this as I didn't checked with |
|
Closed by #5952. |
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
Do you want to request a feature or report a bug?
Bug
What did you do?
Setup is a single Traefik instance acting as Ingress sending requests to a Service that contains a single Pod. Cause the Pod to be unready for just long enough to be removed from the Service. Immediately make the Pod ready again.
In the setup I am using the readiness check is configured as such that it takes 11 seconds of the Pod being unready for it to be marked as unready and be removed from the service.
The test application we have put together allows us to control how it responds to the readiness check. Running the following commands repeatedly eventually triggers the condition.
kubectl -n experiment exec healthtest-blue-app-5b696d58cd-mtvj5 -- curl -XPOST http://localhost:8000/api/health/ill; sleep 11; kubectl -n experiment exec healthtest-blue-app-5b696d58cd-mtvj5 -- curl -XPOST http://localhost:8000/api/health/healthy;Note: In our domain ready == healthy and unready == ill.
What did you expect to see?
Traefik will have, at most, a short time when it has no Pods to send requests to, which results in 503 responses. After the Pod returns to ready Traefik sends requests to that Pod and no long responds with 503.
What did you see instead?
Note that this does not happen every time. The steps may need to be repeated a few times to trigger the bug.
When it does trigger, Traefik continues to respond with 503 even after the logs indicate that the Pod being available has been communicated to it by Kubernetes.
I've also seen it successfully serve requests and then remove the Pod from load balancing. For example this result of requesting the health status of the application while triggering the bug:
It starts by the application in the Pod responding that it is healthy. Then it is made ill (by the commands above). At this point it is not considered unready by Kubernetes and continues to serve requests. After about 11 seconds the application is switched back to healthy. Shortly after that traefik responds with Service Unavailable. It will continue with Service Unavailable until I trigger another readiness change or restart Traefik.
Output of
traefik version: (What version of Traefik are you using?)What is your environment & configuration (arguments, toml, provider, platform, ...)?
Traefik is running as a Kubernetes Ingress. Kubernetes is version 1.16.2.
If applicable, please paste the log output in DEBUG level (
--log.level=DEBUGswitch)Line 1: Responds with 200
Line 3: Configuration update from kubernetes with no servers defined
Line 15: Configuration update 2 seconds later with one server defined
Line 16: Configuration ignored because it is the same as the internal model
Line 17: First configuration now applied and responds with 503 even though there is a ready server
Note that these logs are from a similar reproduction as described above, but at a different time, which is why the timestamps are different.
The text was updated successfully, but these errors were encountered: