Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Question: Does the pod need to talk to the master to restart? #23556

Closed
yoni-tock opened this issue Mar 28, 2016 · 109 comments
Closed

Question: Does the pod need to talk to the master to restart? #23556

yoni-tock opened this issue Mar 28, 2016 · 109 comments
Assignees
Labels
priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. sig/node Categorizes an issue or PR as relevant to SIG Node.

Comments

@yoni-tock
Copy link

We had a micro-outage the other day when one of the machines in our cluster stopped trying to restart. On startup, it hit a transient error that prevented the server from starting up, but the pod did not try to restart again after that. The logs showed nothing between when it got stuck starting up and when I initiated a manual restart 20 minutes later. It seems we hit this issue during a network partition, though we are still investigating.

Does the pod need to talk to the master in order for a restart to be triggered?

Attached is our configuration file, including the restart policy apiserverProdConfig.txt

Thanks!

We're using Kubernetes 1.2.0

@roberthbailey
Copy link
Contributor

/cc @brendandburns @kubernetes/goog-node

Can you clarify a bit: what was restarting, a machine, a pod, or both?

"one of the machines in our cluster stopped trying to restart" vs. "the pod did not try to restart again after that"

@robin-anil
Copy link

To clarify the original question

Our Api job running in the container did not restart after going down even though the ping handler was not working which the kubelet use to check for aliveness. This happened while there was a network outage.
We are baffled by this and it happened only once. So the question was whether the POD itself need to talk to the master when aliveness fails to decide to re-spin up.

So to give more context and where we are in our investigation:

Just a few hours ago we discovered that this is an issue with the container not being able to connect to the DNS server. When we changed the resolv.conf contents in the container to match the one on the VM outside the container, we were able to connect to the outside world.

@yujuhong
Copy link
Contributor

@r-tock kubelet doesn't need to rely on other components to continue managing the containers. However, if kubelet got restarted during the network outage, the new kubelet instance wouldn't know any pod/specs until it talks to the api server. This is due to the lack of persistent checkpoint on the node (the issue to add checkpointing: #489). Could you check the kubelet log to see if it got restarted during that time?

@roberthbailey
Copy link
Contributor

The kubelet healthchecking a pod should not rely on network connectivity between the kubelet and the apiserver. As @yujuhong said, once the kubelet has the pod definition, it will run the pod and healthcheck it even if the apiserver goes down and the kubelet should certainly restart a failed container without needing to contact the apiserver (unless the kubelet restarts).

When we changed the resolv.conf contents in the container to match the one on the VM outside the container, we were able to connect to the outside world.

Are you saying that a misconfigured resolv.conf made you lose all network connectivity (or was it just name resolution)? Could you get to the outside world by IP address?

@robin-anil
Copy link

Yes we can get to the outside world by IP. However since we use external
libraries like Google pubsub Facebook login we can't change that fully to
make our server work
On Mar 30, 2016 1:15 AM, "Robert Bailey" notifications@github.com wrote:

The kubelet healthchecking a pod should not rely on network connectivity
between the kubelet and the apiserver. As @yujuhong
https://github.com/yujuhong said, once the kubelet has the pod
definition, it will run the pod and healthcheck it even if the apiserver
goes down and the kubelet should certainly restart a failed container
without needing to contact the apiserver (unless the kubelet restarts).

When we changed the resolv.conf contents in the container to match the one
on the VM outside the container, we were able to connect to the outside
world.

Are you saying that a misconfigured resolv.conf made you lose all network
connectivity (or was it just name resolution)? Could you get to the outside
world by IP address?


You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#23556 (comment)

@roberthbailey
Copy link
Contributor

Ok, I just wanted to verify that networking wasn't entirely broken (just name resolution).

@thockin
Copy link
Member

thockin commented Mar 30, 2016

Can you clarify what the "bad" resolv.conf says?

@ArtfulCoder P0 to triage

@thockin
Copy link
Member

thockin commented Mar 30, 2016

To clarify: the way kube-dns works is taht we configure your container DNS nameserver to point to a pod running in the cluster. That pod answers cluster.local names and forwards and other DNS to the upstream DNS servers. We need to understand which part of this chain breaks down.

@robin-anil
Copy link

search default.svc.cluster.local svc.cluster.local cluster.local c.rapid-depot-817.internal. google.internal.

nameserver 10.219.240.10
On Mar 30, 2016 10:57 AM, "Tim Hockin" notifications@github.com wrote:

To clarify: the way kube-dns works is taht we configure your container DNS
nameserver to point to a pod running in the cluster. That pod answers
cluster.local names and forwards and other DNS to the upstream DNS
servers. We need to understand which part of this chain breaks down.


You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#23556 (comment)

@ArtfulCoder ArtfulCoder self-assigned this Mar 30, 2016
@ArtfulCoder
Copy link
Contributor

@r-tock

  1. what do you get when you run
    kubectl get svc --namespace=kube-system and
    kubectl get ep --namespace=kube-system
  2. Do you think its plausible that your code is changing the /etc/resolv.conf file ?
  3. Are the search paths on one line or multiple lines ? the way you pasted it, it seems that the search paths are on multiple lines (ideally, should be on one line)
  4. What base image is the container running on ? (ubuntu / busybox (which ver) / scratch )
  5. What does ip 10.219.240.10 correspond to ? Is it the service ip of the DNS service in the cluster ?

@ArtfulCoder ArtfulCoder added the priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. label Mar 30, 2016
@robin-anil
Copy link

robinanil 11:31:45 :~/work/production/apiserver$ kubectl get svc --namespace=kube-system
NAME                   CLUSTER-IP       EXTERNAL-IP   PORT(S)         AGE
default-http-backend   10.239.251.205   nodes         80/TCP          5d
heapster               10.239.242.40    <none>        80/TCP          5d
kube-dns               10.239.240.10    <none>        53/UDP,53/TCP   5d
kubernetes-dashboard   10.239.243.190   <none>        80/TCP          5d
robinanil 11:31:55 :~/work/production/apiserver$ kubectl get ep --namespace=kube-system
NAME                   ENDPOINTS                     AGE
default-http-backend   10.236.0.5:8080               5d
heapster               10.236.2.2:8082               5d
kube-dns               10.236.0.3:53,10.236.0.3:53   5d
kubernetes-dashboard   10.236.2.5:9090               5d
  1. No we are not changing it.
  2. Yes, Gmail seem to have moved it to the new line. its all on one line.
  3. base image is running on https://github.com/phusion/baseimage-docker
  4. I don't know every cluster seem to have a different IP. I thought you would know. I figured out that IP is in the subnet range of the cluster.

@ArtfulCoder
Copy link
Contributor

  1. The issue is that the nameserver in /etc/resolv.conf should have said 10.239.240.10.
  2. What is /etc/resolv.conf on the node(/host/machine) of the offending container.
  3. What does sudo ps -ef |grep kubelet on that node give ? I am looking for the command line args of the kubelet.

@robin-anil
Copy link

I think I may have pasted the previous resolv.conf entry from our preprod cluster. For our prod cluster it is the right thing. Note that you can commandeer our preprod cluster to do any experiment.
resolv.conf from container within the prod cluster.

Prod setup Below: (DNS works here)

robinanil 11:31:45 :~/work/production/apiserver$ kubectl get svc --namespace=kube-system
NAME                   CLUSTER-IP       EXTERNAL-IP   PORT(S)         AGE
default-http-backend   10.239.251.205   nodes         80/TCP          5d
heapster               10.239.242.40    <none>        80/TCP          5d
kube-dns               10.239.240.10    <none>        53/UDP,53/TCP   5d
kubernetes-dashboard   10.239.243.190   <none>        80/TCP          5d
robinanil 11:31:55 :~/work/production/apiserver$ kubectl get ep --namespace=kube-system
NAME                   ENDPOINTS                     AGE
default-http-backend   10.236.0.5:8080               5d
heapster               10.236.2.2:8082               5d
kube-dns               10.236.0.3:53,10.236.0.3:53   5d
kubernetes-dashboard   10.236.2.5:9090               5d
search default.svc.cluster.local svc.cluster.local cluster.local c.rapid-depot-817.internal. google.internal.
nameserver 10.239.240.10
options ndots:5
domain c.rapid-depot-817.internal.
search c.rapid-depot-817.internal. google.internal.
nameserver 169.254.169.254
root     19784     1  1 Mar29 ?        00:25:22 /usr/local/bin/kubelet --api-servers=https://104.197.212.218 --enable-debugging-handlers=true --cloud-provider=gce --config=/etc/kubernetes/manifests --allow-privileged=True --v=2 --cluster-dns=10.239.240.10 --cluster-domain=cluster.local --configure-cbr0=true --cgroup-root=/ --system-cgroups=/system --runtime-cgroups=/docker-daemon --kubelet-cgroups=/kubelet --node-labels=cloud.google.com/gke-nodepool=default-pool --babysit-daemons=true

@robin-anil
Copy link

This is the equivalent set of info from our preprod cluster. The lack of DNS issue is reproducible there

PreProd setup Below: DNS Does not work here.

robinanil 12:25:00 :~/work/production/apiserver$ kubectl get svc --namespace=kube-system
NAME                   CLUSTER-IP       EXTERNAL-IP   PORT(S)         AGE
default-http-backend   10.219.240.219   nodes         80/TCP          20h
heapster               10.219.250.180   <none>        80/TCP          20h
kube-dns               10.219.240.10    <none>        53/UDP,53/TCP   20h
kubernetes-dashboard   10.219.253.98    <none>        80/TCP          20h
robinanil 12:25:05 :~/work/production/apiserver$ kubectl get ep --namespace=kube-system
NAME                   ENDPOINTS         AGE
default-http-backend                     20h
heapster               10.216.0.4:8082   20h
kube-dns               <none>            20h
kubernetes-dashboard   10.216.0.6:9090   20h
search default.svc.cluster.local svc.cluster.local cluster.local c.rapid-depot-817.internal. google.internal.
nameserver 10.219.240.10
options ndots:5
domain c.rapid-depot-817.internal.
search c.rapid-depot-817.internal. google.internal.
nameserver 169.254.169.254

robinanil@gke-apiserver-preprod-2016-03-29t20-41-14-de5522f9-node-3ryd:~$ sudo ps -ef |grep kubelet
root      3392  3370  0 Mar29 ?        00:00:02 /bin/bash /usr/sbin/kubelet-checker.sh
root      3418     1  1 Mar29 ?        00:12:41 /usr/local/bin/kubelet --api-servers=https://104.197.237.200 --enable-debugging-handlers=true --cloud-provider=gce --config=/etc/kubernetes/manifests --allow-privileged=True --v=2 --cluster-dns=10.219.240.10 --cluster-domain=cluster.local --configure-cbr0=true --cgroup-root=/ --system-cgroups=/system --runtime-cgroups=/docker-daemon --kubelet-cgroups=/kubelet --node-labels=cloud.google.com/gke-nodepool=default-pool --babysit-daemons=true
1004      8103  7724  0 16:53 pts/0    00:00:00 grep kubelet

@ArtfulCoder
Copy link
Contributor

To clarify, where do you have DNS issues ?
In the kubernetes cluster ? or outside the kubernetes cluster ?
I am assuming you mean prepod cluster means not running kubernetes ?

@robin-anil
Copy link

We are seeing DNS issues inside the docker container for connecting with VMs on Google Cloud and public domains.

We are using kubernetes in both preprod and prod clusters.

@ArtfulCoder
Copy link
Contributor

what do you get when you run
kubectl get svc --namespace=kube-system and
kubectl get ep --namespace=kube-system

on the offending cluster ?

@ArtfulCoder
Copy link
Contributor

  1. Is the DNS issue still reproducible ?
  2. Is it an issue on every node of the offending cluster ?

@robin-anil
Copy link

  1. Yes DNS issue is still reproducible.
  2. The preprod cluster has only 1 node.

@robin-anil
Copy link

robinanil 12:25:00 :~/work/production/apiserver$ kubectl get svc --namespace=kube-system
NAME                   CLUSTER-IP       EXTERNAL-IP   PORT(S)         AGE
default-http-backend   10.219.240.219   nodes         80/TCP          20h
heapster               10.219.250.180   <none>        80/TCP          20h
kube-dns               10.219.240.10    <none>        53/UDP,53/TCP   20h
kubernetes-dashboard   10.219.253.98    <none>        80/TCP          20h
robinanil 12:25:05 :~/work/production/apiserver$ kubectl get ep --namespace=kube-system
NAME                   ENDPOINTS         AGE
default-http-backend                     20h
heapster               10.216.0.4:8082   20h
kube-dns               <none>            20h
kubernetes-dashboard   10.216.0.6:9090   20h

@ArtfulCoder
Copy link
Contributor

KubeDNS is not running at all on your prepod setup.
Can you run
kubectl get rc --namespace=kube-system
and
kubectl get pod --namespace=kube-system

If there is an error on the kubedns start, can you get the logs for the pod, by running kubectl get pod

@robin-anil
Copy link

robinanil 12:25:10 :~/work/production/apiserver$ kubectl get rc --namespace=kube-system
NAME                          DESIRED   CURRENT   AGE
heapster-v1.0.0               1         1         20h
kube-dns-v11                  1         1         20h
kubernetes-dashboard-v1.0.0   1         1         20h
l7-lb-controller-v0.6.0       1         1         20h
robinanil 12:35:35 :~/work/production/apiserver$ kubectl get pod --namespace=kube-system
NAME                                                                                 READY     STATUS             RESTARTS   AGE
fluentd-cloud-logging-gke-apiserver-preprod-2016-03-29t20-41-14-de5522f9-node-3ryd   1/1       Running            0          20h
heapster-v1.0.0-vgh6i                                                                1/1       Running            0          20h
kube-dns-v11-a2yqb                                                                   0/4       Pending            0          20h
kube-proxy-gke-apiserver-preprod-2016-03-29t20-41-14-de5522f9-node-3ryd              1/1       Running            0          20h
kubernetes-dashboard-v1.0.0-mt3nt                                                    1/1       Running            0          20h
l7-lb-controller-v0.6.0-kdju7                                                        1/2       CrashLoopBackOff   359        20h

@robin-anil
Copy link

Here is the kubelet.log

I0330 17:34:38.637596    3418 container_manager_linux.go:524] Found 42 PIDs in root, 42 of them are not to be moved
I0330 17:34:45.526059    3418 server.go:1096] GET /healthz: (34.59µs) 200 [[curl/7.26.0] 127.0.0.1:47434]
I0330 17:34:48.168089    3418 server.go:1096] GET /healthz: (45.168µs) 200 [[Go 1.1 package http] 127.0.0.1:47438]
I0330 17:34:49.421767    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:34:49.421822    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:34:55.547619    3418 server.go:1096] GET /healthz: (29.431µs) 200 [[curl/7.26.0] 127.0.0.1:47443]
I0330 17:35:03.422080    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:35:03.422142    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:35:05.014100    3418 server.go:1096] GET /stats/summary/: (9.427336ms) 200 [[Go-http-client/1.1] 10.216.0.4:38620]
I0330 17:35:05.568902    3418 server.go:1096] GET /healthz: (34.251µs) 200 [[curl/7.26.0] 127.0.0.1:47487]
I0330 17:35:15.590656    3418 server.go:1096] GET /healthz: (32.457µs) 200 [[curl/7.26.0] 127.0.0.1:47497]
I0330 17:35:16.422340    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:35:16.422402    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:35:25.612846    3418 server.go:1096] GET /healthz: (39.114µs) 200 [[curl/7.26.0] 127.0.0.1:47504]
I0330 17:35:30.422013    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:35:30.422079    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:35:35.634465    3418 server.go:1096] GET /healthz: (37.54µs) 200 [[curl/7.26.0] 127.0.0.1:47514]
I0330 17:35:38.646717    3418 container_manager_linux.go:524] Found 42 PIDs in root, 42 of them are not to be moved
I0330 17:35:44.832805    3418 kubelet.go:2410] SyncLoop (PLEG): "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)", event: &pleg.PodLifecycleEvent{ID:"f772010c-f5ee-11e5-bc2d-42010af00059", Type:"ContainerStarted", Data:"a139d2158e54ad1c3cc0b6852eafd854ada142c8d8560072ac06852b72400713"}
I0330 17:35:45.659006    3418 server.go:1096] GET /healthz: (30.364µs) 200 [[curl/7.26.0] 127.0.0.1:47523]
I0330 17:35:48.168402    3418 server.go:1096] GET /healthz: (45.748µs) 200 [[Go 1.1 package http] 127.0.0.1:47536]
I0330 17:35:55.679845    3418 server.go:1096] GET /healthz: (35.465µs) 200 [[curl/7.26.0] 127.0.0.1:47541]
I0330 17:36:05.052013    3418 server.go:1096] GET /stats/summary/: (46.225715ms) 200 [[Go-http-client/1.1] 10.216.0.4:38620]
I0330 17:36:05.699903    3418 server.go:1096] GET /healthz: (27.765µs) 200 [[curl/7.26.0] 127.0.0.1:47552]
I0330 17:36:15.726194    3418 server.go:1096] GET /healthz: (29.745µs) 200 [[curl/7.26.0] 127.0.0.1:47562]
I0330 17:36:25.747561    3418 server.go:1096] GET /healthz: (30.778µs) 200 [[curl/7.26.0] 127.0.0.1:47569]
I0330 17:36:34.497683    3418 prober.go:104] Liveness probe for "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059):l7-lb-controller" failed (failure): HTTP probe failed with statuscode: 500
I0330 17:36:34.497795    3418 kubelet.go:2436] SyncLoop (container unhealthy): "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:36:34.498450    3418 manager.go:1748] pod "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)" container "l7-lb-controller" is unhealthy, it will be killed and re-created.
I0330 17:36:34.498485    3418 manager.go:1368] Killing container "a139d2158e54ad1c3cc0b6852eafd854ada142c8d8560072ac06852b72400713 l7-lb-controller kube-system/l7-lb-controller-v0.6.0-kdju7" with 600 second grace period
I0330 17:36:34.517598    3418 manager.go:1400] Container "a139d2158e54ad1c3cc0b6852eafd854ada142c8d8560072ac06852b72400713 l7-lb-controller kube-system/l7-lb-controller-v0.6.0-kdju7" exited after 19.090709ms
I0330 17:36:35.042641    3418 kubelet.go:2410] SyncLoop (PLEG): "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)", event: &pleg.PodLifecycleEvent{ID:"f772010c-f5ee-11e5-bc2d-42010af00059", Type:"ContainerDied", Data:"a139d2158e54ad1c3cc0b6852eafd854ada142c8d8560072ac06852b72400713"}
I0330 17:36:35.046726    3418 kubelet.go:2410] SyncLoop (PLEG): "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)", event: &pleg.PodLifecycleEvent{ID:"f772010c-f5ee-11e5-bc2d-42010af00059", Type:"ContainerStarted", Data:"269cb60df3436c719e2098a520a40574c01c4f0bd9a878714539e81923e25002"}
I0330 17:36:35.770028    3418 server.go:1096] GET /healthz: (39.014µs) 200 [[curl/7.26.0] 127.0.0.1:47583]
I0330 17:36:38.656165    3418 container_manager_linux.go:524] Found 42 PIDs in root, 42 of them are not to be moved
I0330 17:36:45.793828    3418 server.go:1096] GET /healthz: (63.883µs) 200 [[curl/7.26.0] 127.0.0.1:47597]
I0330 17:36:48.168826    3418 server.go:1096] GET /healthz: (41.647µs) 200 [[Go 1.1 package http] 127.0.0.1:47601]
I0330 17:36:55.816158    3418 server.go:1096] GET /healthz: (41.983µs) 200 [[curl/7.26.0] 127.0.0.1:47606]
I0330 17:37:05.017450    3418 server.go:1096] GET /stats/summary/: (10.54391ms) 200 [[Go-http-client/1.1] 10.216.0.4:38620]
I0330 17:37:05.838444    3418 server.go:1096] GET /healthz: (36.387µs) 200 [[curl/7.26.0] 127.0.0.1:47617]
I0330 17:37:15.861894    3418 server.go:1096] GET /healthz: (27.683µs) 200 [[curl/7.26.0] 127.0.0.1:47627]
I0330 17:37:25.883513    3418 server.go:1096] GET /healthz: (36.218µs) 200 [[curl/7.26.0] 127.0.0.1:47633]
I0330 17:37:34.496921    3418 prober.go:104] Liveness probe for "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059):l7-lb-controller" failed (failure): HTTP probe failed with statuscode: 500
I0330 17:37:34.497022    3418 kubelet.go:2436] SyncLoop (container unhealthy): "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:37:34.497542    3418 manager.go:1748] pod "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)" container "l7-lb-controller" is unhealthy, it will be killed and re-created.
I0330 17:37:34.497573    3418 manager.go:1368] Killing container "269cb60df3436c719e2098a520a40574c01c4f0bd9a878714539e81923e25002 l7-lb-controller kube-system/l7-lb-controller-v0.6.0-kdju7" with 600 second grace period
I0330 17:37:34.519889    3418 manager.go:1400] Container "269cb60df3436c719e2098a520a40574c01c4f0bd9a878714539e81923e25002 l7-lb-controller kube-system/l7-lb-controller-v0.6.0-kdju7" exited after 22.299068ms
I0330 17:37:34.520119    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:37:34.520174    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:37:35.351632    3418 kubelet.go:2410] SyncLoop (PLEG): "l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)", event: &pleg.PodLifecycleEvent{ID:"f772010c-f5ee-11e5-bc2d-42010af00059", Type:"ContainerDied", Data:"269cb60df3436c719e2098a520a40574c01c4f0bd9a878714539e81923e25002"}
I0330 17:37:35.355286    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:37:35.355353    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:37:35.902937    3418 server.go:1096] GET /healthz: (29.758µs) 200 [[curl/7.26.0] 127.0.0.1:47646]
I0330 17:37:38.664379    3418 container_manager_linux.go:524] Found 42 PIDs in root, 42 of them are not to be moved
I0330 17:37:45.957227    3418 server.go:1096] GET /healthz: (29.515µs) 200 [[curl/7.26.0] 127.0.0.1:47657]
I0330 17:37:48.166842    3418 server.go:1096] GET /healthz: (28.74µs) 200 [[Go 1.1 package http] 127.0.0.1:47661]
I0330 17:37:48.428495    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:37:48.428546    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:37:55.976881    3418 server.go:1096] GET /healthz: (32.901µs) 200 [[curl/7.26.0] 127.0.0.1:47666]
I0330 17:38:02.436071    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:38:02.436142    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:38:05.012140    3418 server.go:1096] GET /stats/summary/: (11.410237ms) 200 [[Go-http-client/1.1] 10.216.0.4:38620]
I0330 17:38:05.996496    3418 server.go:1096] GET /healthz: (31.357µs) 200 [[curl/7.26.0] 127.0.0.1:47675]
I0330 17:38:13.421786    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:38:13.421835    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:38:16.018800    3418 server.go:1096] GET /healthz: (29.029µs) 200 [[curl/7.26.0] 127.0.0.1:47685]
I0330 17:38:24.421977    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:38:24.422040    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:38:26.039681    3418 server.go:1096] GET /healthz: (28.026µs) 200 [[curl/7.26.0] 127.0.0.1:47693]
I0330 17:38:36.063212    3418 server.go:1096] GET /healthz: (42.857µs) 200 [[curl/7.26.0] 127.0.0.1:47704]
I0330 17:38:37.421751    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:38:37.421811    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"
I0330 17:38:38.675196    3418 container_manager_linux.go:524] Found 42 PIDs in root, 42 of them are not to be moved
I0330 17:38:46.085123    3418 server.go:1096] GET /healthz: (29.198µs) 200 [[curl/7.26.0] 127.0.0.1:47711]
I0330 17:38:48.166510    3418 server.go:1096] GET /healthz: (44.875µs) 200 [[Go 1.1 package http] 127.0.0.1:47715]
I0330 17:38:50.430255    3418 manager.go:2047] Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)
E0330 17:38:50.430305    3418 pod_workers.go:138] Error syncing pod f772010c-f5ee-11e5-bc2d-42010af00059, skipping: failed to "StartContainer" for "l7-lb-controller" with CrashLoopBackOff: "Back-off 5m0s restarting failed container=l7-lb-controller pod=l7-lb-controller-v0.6.0-kdju7_kube-system(f772010c-f5ee-11e5-bc2d-42010af00059)"

@ArtfulCoder
Copy link
Contributor

can you run:
kubectl describe pod kube-dns-v11-a2yqb --namespace=kube-system

@robin-anil
Copy link

robinanil 12:39:55 :~/work/production/apiserver$ kubectl describe pod kube-dns-v11-a2yqb --namespace=kube-system
Name:       kube-dns-v11-a2yqb
Namespace:  kube-system
Node:       /
Labels:     k8s-app=kube-dns,kubernetes.io/cluster-service=true,version=v11
Status:     Pending
IP:     
Controllers:    ReplicationController/kube-dns-v11
Containers:
  etcd:
    Image:  gcr.io/google_containers/etcd-amd64:2.2.1
    Port:   
    Command:
      /usr/local/bin/etcd
      -data-dir
      /var/etcd/data
      -listen-client-urls
      http://127.0.0.1:2379,http://127.0.0.1:4001
      -advertise-client-urls
      http://127.0.0.1:2379,http://127.0.0.1:4001
      -initial-cluster-token
      skydns-etcd
    QoS Tier:
      cpu:  Guaranteed
      memory:   Burstable
    Limits:
      memory:   500Mi
      cpu:  100m
    Requests:
      memory:   50Mi
      cpu:  100m
    Environment Variables:
  kube2sky:
    Image:  gcr.io/google_containers/kube2sky:1.14
    Port:   
    Args:
      --domain=cluster.local
    QoS Tier:
      memory:   Burstable
      cpu:  Guaranteed
    Limits:
      cpu:  100m
      memory:   200Mi
    Requests:
      cpu:  100m
      memory:   50Mi
    Liveness:   http-get http://:8080/healthz delay=60s timeout=5s period=10s #success=1 #failure=5
    Readiness:  http-get http://:8081/readiness delay=30s timeout=5s period=10s #success=1 #failure=3
    Environment Variables:
  skydns:
    Image:  gcr.io/google_containers/skydns:2015-10-13-8c72f8c
    Ports:  53/UDP, 53/TCP
    Args:
      -machines=http://127.0.0.1:4001
      -addr=0.0.0.0:53
      -ns-rotate=false
      -domain=cluster.local.
    QoS Tier:
      memory:   Burstable
      cpu:  Guaranteed
    Limits:
      cpu:  100m
      memory:   200Mi
    Requests:
      memory:   50Mi
      cpu:  100m
    Environment Variables:
  healthz:
    Image:  gcr.io/google_containers/exechealthz:1.0
    Port:   8080/TCP
    Args:
      -cmd=nslookup kubernetes.default.svc.cluster.local 127.0.0.1 >/dev/null
      -port=8080
    QoS Tier:
      cpu:  Guaranteed
      memory:   Guaranteed
    Limits:
      memory:   20Mi
      cpu:  10m
    Requests:
      cpu:  10m
      memory:   20Mi
    Environment Variables:
Volumes:
  etcd-storage:
    Type:   EmptyDir (a temporary directory that shares a pod's lifetime)
    Medium: 
  default-token-7nk49:
    Type:   Secret (a volume populated by a Secret)
    SecretName: default-token-7nk49
Events:
  FirstSeen LastSeen    Count   From            SubobjectPath   Type        Reason          Message
  --------- --------    -----   ----            -------------   --------    ------          -------
  20h       16s     4285    {default-scheduler }            Warning     FailedScheduling    pod (kube-dns-v11-a2yqb) failed to fit in any node
fit failure on node (gke-apiserver-preprod-2016-03-29t20-41-14-de5522f9-node-3ryd): Node didn't have enough resource: CPU, requested: 310, used: 810, capacity: 1000



@roberthbailey
Copy link
Contributor

Can you manually scale your cluster to have 1 extra node?

@ArtfulCoder
Copy link
Contributor

yeah, it's
Node didn't have enough resource: CPU, requested: 310, used: 810, capacity: 1000

@robin-anil
Copy link

Could you paste the command for that?

@dchen1107
Copy link
Member

I looked into this very issue yesterday for our gke cluster, and here is what I found yesterday (copy & paste from gke buganiza):

There are more than one docker daemon instances running on the master node:

# ps -ef | grep docker
root      3662     1  0 Mar27 ?        00:00:11 /usr/bin/docker daemon -p /var/run/docker.pid --bridge=cbr0 --iptables=false --ip-masq=false --log-level=warn
root      3663     1 93 Mar27 ?        23:35:16 /usr/bin/docker daemon -p /var/run/docker.pid --bridge=cbr0 --iptables=false --ip-masq=false --log-level=warn

When it happens, docker ps will hang, and docker version returns successfully:

I checked the logs, and found our babysitter daemon tried to do the clean up by running /etc/init.d/docker stop, but failed because the /var/run/docker.pid has a different pid recorded than the one of pidof docker returns. 

Looks like there is a race upon starting docker daemon. I tried to reproduce the issue on the node by killing daemon process, killing babysitter scripts, or manually run /etc/init.d/docker start|stop|restart, and couldn't reproduce the issue yet. 

To fix the issue I have to kill those docker daemons, and the babysitter will kick in and restart the daemon properly. But at the first place, who starts the second daemon is still question.

I also tried to remove one of possibilities of restarting docker daemon through: #23593. But it looks like it doesn't remove all possibilities based on our tests. Another possibility is introduced by docker load. In 1.2 release, someone introduce docker load to load kube-proxy image on every worker node which might hang docker daemon, thus there is a script to detect such issue and start docker daemon.

So my plan is to detect the issue and remedy the system by killing all running daemons.

EDIT: @ArtfulCoder has pr #23662 to remedy the system here.

@a-robinson a-robinson added team/cluster sig/node Categorizes an issue or PR as relevant to SIG Node. labels Mar 31, 2016
@robin-anil
Copy link

Saw a restart today morning 30 mins ago. This looks like a memory issue.

FIRSTSEEN   LASTSEEN   COUNT     NAME                   KIND      SUBOBJECT   TYPE      REASON             SOURCE                 MESSAGE
1h          37m        108       apiserver-prod-wmosz   Pod                   Warning   FailedScheduling   {default-scheduler }   pod (apiserver-prod-wmosz) failed to fit in any node
fit failure on node (gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-z1ui): PodFitsHostPorts
fit failure on node (gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-bpsn): PodFitsHostPorts

1h        37m       28        apiserver-prod-wmosz   Pod                 Warning   FailedScheduling   {default-scheduler }   pod (apiserver-prod-wmosz) failed to fit in any node
fit failure on node (gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-bpsn): PodFitsHostPorts
fit failure on node (gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-z1ui): PodFitsHostPorts

36m       36m       1         apiserver-prod-wmosz                                        Pod                                         Normal    Scheduled               {default-scheduler }                                                     Successfully assigned apiserver-prod-wmosz to gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{apiserver-prod}   Normal    Pulling                 {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      pulling image "gcr.io/rapid-depot-817/apiserver:prod"
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{apiserver-prod}   Normal    Pulled                  {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Successfully pulled image "gcr.io/rapid-depot-817/apiserver:prod"
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{apiserver-prod}   Normal    Created                 {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Created container with docker id a14fcdad7462
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{apiserver-prod}   Normal    Started                 {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Started container with docker id a14fcdad7462
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{logstash}         Normal    Pulling                 {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      pulling image "gcr.io/rapid-depot-817/logstash-sidecar:latest"
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{logstash}         Normal    Pulled                  {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Successfully pulled image "gcr.io/rapid-depot-817/logstash-sidecar:latest"
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{logstash}         Normal    Created                 {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Created container with docker id 66ae1ecb8a23
36m       36m       1         apiserver-prod-wmosz                                        Pod       spec.containers{logstash}         Normal    Started                 {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Started container with docker id 66ae1ecb8a23
37m       37m       2         apiserver-prod-ztr3z                                        Pod       spec.containers{apiserver-prod}   Warning   Unhealthy               {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Liveness probe failed: Get http://10.12.1.3:6060/monitorz/ping: dial tcp 10.12.1.3:6060: connection refused
37m       37m       1         apiserver-prod-ztr3z                                        Pod       spec.containers{apiserver-prod}   Warning   Unhealthy               {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Liveness probe failed: Get http://10.12.1.3:6060/monitorz/ping: net/http: request canceled while waiting for connection
37m       37m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Warning   SystemOOM               {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      System OOM encountered
37m       37m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Normal    Starting                {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Starting kubelet.
37m       37m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Normal    NodeHasSufficientDisk   {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Node gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida status is now: NodeHasSufficientDisk
37m       37m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Normal    NodeNotReady            {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Node gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida status is now: NodeNotReady
37m       37m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Warning   SystemOOM               {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      System OOM encountered
37m       37m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Normal    NodeReady               {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}      Node gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida status is now: NodeReady
36m       36m       1         gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Node                                        Normal    Starting                {kube-proxy gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Starting kube-proxy.
kubectl get events --namespace=kube-system
FIRSTSEEN   LASTSEEN   COUNT     NAME                                                                              KIND      SUBOBJECT                                TYPE      REASON      SOURCE                                                                MESSAGE
37m         37m        1         fluentd-cloud-logging-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Pod       spec.containers{fluentd-cloud-logging}   Normal    Pulled      {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Container image "gcr.io/google_containers/fluentd-gcp:1.18" already present on machine
37m         37m        1         fluentd-cloud-logging-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Pod       spec.containers{fluentd-cloud-logging}   Normal    Created     {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Created container with docker id 543680c47057
37m         37m        1         fluentd-cloud-logging-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida   Pod       spec.containers{fluentd-cloud-logging}   Normal    Started     {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Started container with docker id 543680c47057
37m         37m        1         kube-proxy-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida              Pod       spec.containers{kube-proxy}              Normal    Pulled      {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Container image "gcr.io/google_containers/kube-proxy:6a3c7bde4710fbeb04cee371779c437b" already present on machine
37m         37m        1         kube-proxy-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida              Pod       spec.containers{kube-proxy}              Normal    Created     {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Created container with docker id aee12a7bfdfc
37m         37m        1         kube-proxy-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida              Pod       spec.containers{kube-proxy}              Normal    Started     {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Started container with docker id aee12a7bfdfc
38m         38m        1         kubernetes-dashboard-v1.0.0-p0az9                                                 Pod       spec.containers{kubernetes-dashboard}    Warning   Unhealthy   {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Liveness probe failed: Get http://10.12.1.2:9090/: read tcp 10.12.1.2:9090: connection reset by peer
38m         38m        2         kubernetes-dashboard-v1.0.0-p0az9                                                 Pod       spec.containers{kubernetes-dashboard}    Warning   Unhealthy   {kubelet gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida}   Liveness probe failed: Get http://10.12.1.2:9090/: dial tcp 10.12.1.2:9090: connection refused

robinanil@gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida:~$ sudo docker ps
CONTAINER ID        IMAGE                                                                  COMMAND                  CREATED             STATUS              PORTS                              NAMES
66ae1ecb8a23        gcr.io/rapid-depot-817/logstash-sidecar:latest                         "/usr/bin/supervisord"   39 minutes ago      Up 39 minutes                                          k8s_logstash.68b377ef_apiserver-prod-wmosz_default_e0580d09-f73d-11e5-8ab5-42010af000c1_f4a10636
a14fcdad7462        gcr.io/rapid-depot-817/apiserver:prod                                  "/usr/bin/supervisord"   39 minutes ago      Up 39 minutes                                          k8s_apiserver-prod.c8da9b4_apiserver-prod-wmosz_default_e0580d09-f73d-11e5-8ab5-42010af000c1_37d4e189
543680c47057        gcr.io/google_containers/fluentd-gcp:1.18                              "/bin/sh -c '/usr/sbi"   39 minutes ago      Up 39 minutes                                          k8s_fluentd-cloud-logging.fe59dd68_fluentd-cloud-logging-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida_kube-system_da7e41ef0372c29c65a24b417b5dd69f_97c412f3
aee12a7bfdfc        gcr.io/google_containers/kube-proxy:6a3c7bde4710fbeb04cee371779c437b   "/bin/sh -c 'kube-pro"   39 minutes ago      Up 39 minutes                                          k8s_kube-proxy.345ef424_kube-proxy-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida_kube-system_16fa1ca9c32eec40cb9b933bfd317fb5_82c58e5d
dcfe8acdb08b        gcr.io/google_containers/pause:2.0                                     "/pause"                 39 minutes ago      Up 39 minutes       0.0.0.0:6060-6061->6060-6061/tcp   k8s_POD.7a2450_apiserver-prod-wmosz_default_e0580d09-f73d-11e5-8ab5-42010af000c1_1af43bc7
769669e15719        gcr.io/google_containers/pause:2.0                                     "/pause"                 39 minutes ago      Up 39 minutes                                          k8s_POD.6059dfa2_kube-proxy-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida_kube-system_16fa1ca9c32eec40cb9b933bfd317fb5_8ef8f3b7
3d6583438ef9        gcr.io/google_containers/pause:2.0                                     "/pause"                 39 minutes ago      Up 39 minutes                                          k8s_POD.6059dfa2_fluentd-cloud-logging-gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida_kube-system_da7e41ef0372c29c65a24b417b5dd69f_4b18a11b
[ 8945.053500] aufs au_opts_verify:1570:docker[3979]: dirperm1 breaks the protection by the permission bits on the lower branch
[67416.336368] <file invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=1000
[67416.344184] <file cpuset=8b21b5dd145dd97aac66fe3b56259464c3465cb0622c0b783addb2899644777f mems_allowed=0
[67416.354132] CPU: 0 PID: 4253 Comm: <file Tainted: G         C    3.16.0-4-amd64 #1 Debian 3.16.7-ckt20-1+deb8u4google
[67416.364977] Hardware name: Google Google, BIOS Google 01/01/2011
[67416.371147]  0000000000000000 ffffffff8150db3f ffff8800ba9aa090 ffffffff8150b757
[67416.379276]  0000000000000000 ffffffff810d4f8f 0000000000000000 ffffffff815124be
[67416.387309]  0000000000000200 ffffffff81067993 ffffffff810c26a4 0000000000000000
[67416.395475] Call Trace:
[67416.398067]  [<ffffffff8150db3f>] ? dump_stack+0x41/0x51
[67416.403655]  [<ffffffff8150b757>] ? dump_header+0x76/0x1e8
[67416.409276]  [<ffffffff810d4f8f>] ? smp_call_function_single+0x5f/0xa0
[67416.415929]  [<ffffffff815124be>] ? mutex_lock+0xe/0x2a
[67416.421288]  [<ffffffff81067993>] ? put_online_cpus+0x23/0x80
[67416.427286]  [<ffffffff810c26a4>] ? rcu_oom_notify+0xc4/0xe0
[67416.433078]  [<ffffffff81151c1c>] ? do_try_to_free_pages+0x4ac/0x520
[67416.439592]  [<ffffffff8114088d>] ? oom_kill_process+0x21d/0x370
[67416.445779]  [<ffffffff8114044d>] ? find_lock_task_mm+0x3d/0x90
[67416.452012]  [<ffffffff81140ff3>] ? out_of_memory+0x473/0x4b0
[67416.457911]  [<ffffffff81146dfd>] ? __alloc_pages_nodemask+0x9cd/0xb30
[67416.464656]  [<ffffffff81185fdd>] ? alloc_pages_current+0x9d/0x150
[67416.470970]  [<ffffffff8113f5f0>] ? filemap_fault+0x1a0/0x420
[67416.476893]  [<ffffffff8116548a>] ? __do_fault+0x3a/0xa0
[67416.482335]  [<ffffffff8116804e>] ? do_read_fault.isra.54+0x4e/0x300
[67416.488844]  [<ffffffff8116987c>] ? handle_mm_fault+0x63c/0x11c0
[67416.495031]  [<ffffffff810572b7>] ? __do_page_fault+0x177/0x4f0
[67416.501079]  [<ffffffff811ad1d9>] ? SYSC_newstat+0x29/0x40
[67416.506724]  [<ffffffff81515d28>] ? page_fault+0x28/0x30
[67416.512176] Mem-Info:
[67416.514583] Node 0 DMA per-cpu:
[67416.517957] CPU    0: hi:    0, btch:   1 usd:   0
[67416.522858] CPU    1: hi:    0, btch:   1 usd:   0
[67416.527763] CPU    2: hi:    0, btch:   1 usd:   0
[67416.532672] CPU    3: hi:    0, btch:   1 usd:   0
[67416.537623] Node 0 DMA32 per-cpu:
[67416.541192] CPU    0: hi:  186, btch:  31 usd:   0
[67416.546109] CPU    1: hi:  186, btch:  31 usd:  21
[67416.551020] CPU    2: hi:  186, btch:  31 usd:  14
[67416.555928] CPU    3: hi:  186, btch:  31 usd: 166
[67416.560871] Node 0 Normal per-cpu:
[67416.564654] CPU    0: hi:  186, btch:  31 usd:   0
[67416.569574] CPU    1: hi:  186, btch:  31 usd:   0
[67416.574501] CPU    2: hi:  186, btch:  31 usd:   0
[67416.579548] CPU    3: hi:  186, btch:  31 usd:   0
[67416.584471] active_anon:850656 inactive_anon:51 isolated_anon:0
[67416.584471]  active_file:808 inactive_file:1002 isolated_file:0
[67416.584471]  unevictable:863 dirty:2 writeback:0 unstable:0
[67416.584471]  free:21147 slab_reclaimable:5366 slab_unreclaimable:8021
[67416.584471]  mapped:1288 shmem:224 pagetables:5039 bounce:0
[67416.584471]  free_cma:0
[67416.616615] Node 0 DMA free:14452kB min:292kB low:364kB high:436kB active_anon:716kB inactive_anon:0kB active_file:20kB inactive_file:104kB unevictable:8kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:8kB dirty:0kB writeback:0kB mapped:12kB shmem:0kB slab_reclaimable:28kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:1631 all_unreclaimable? yes
[67416.657200] lowmem_reserve[]: 0 2983 3544 3544
[67416.662441] Node 0 DMA32 free:59804kB min:56632kB low:70788kB high:84948kB active_anon:2890012kB inactive_anon:176kB active_file:3352kB inactive_file:4072kB unevictable:2848kB isolated(anon):0kB isolated(file):0kB present:3129332kB managed:3054876kB mlocked:2852kB dirty:8kB writeback:0kB mapped:4972kB shmem:764kB slab_reclaimable:17032kB slab_unreclaimable:24704kB kernel_stack:6960kB pagetables:17792kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:11434 all_unreclaimable? yes
[67416.707156] lowmem_reserve[]: 0 0 560 560
[67416.711952] Node 0 Normal free:10332kB min:10652kB low:13312kB high:15976kB active_anon:511896kB inactive_anon:28kB active_file:8kB inactive_file:12kB unevictable:596kB isolated(anon):0kB isolated(file):0kB present:628736kB managed:574264kB mlocked:596kB dirty:0kB writeback:0kB mapped:168kB shmem:132kB slab_reclaimable:4404kB slab_unreclaimable:7372kB kernel_stack:1520kB pagetables:2364kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:75 all_unreclaimable? yes
[67416.755384] lowmem_reserve[]: 0 0 0 0
[67416.759943] Node 0 DMA: 10*4kB (UEM) 10*8kB (UEM) 9*16kB (UEM) 7*32kB (EM) 5*64kB (UM) 3*128kB (UEM) 2*256kB (UE) 3*512kB (UEM) 1*1024kB (E) 3*2048kB (EMR) 1*4096kB (M) = 14504kB
[67416.779112] Node 0 DMA32: 1331*4kB (UEM) 744*8kB (UEM) 427*16kB (UE) 320*32kB (UEM) 189*64kB (UEM) 87*128kB (UEM) 16*256kB (UEM) 1*512kB (M) 0*1024kB 0*2048kB 1*4096kB (R) = 60284kB
[67416.798173] Node 0 Normal: 1297*4kB (UEM) 256*8kB (UEM) 52*16kB (UM) 4*32kB (UMR) 6*64kB (UMR) 2*128kB (MR) 2*256kB (R) 1*512kB (R) 1*1024kB (R) 0*2048kB 0*4096kB = 10884kB
[67416.816407] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[67416.824972] 2439 total pagecache pages
[67416.828846] 0 pages in swap cache
[67416.832286] Swap cache stats: add 0, delete 0, find 0/0
[67416.837620] Free swap  = 0kB
[67416.840621] Total swap = 0kB
[67416.843613] 943515 pages RAM
[67416.846619] 0 pages HighMem/MovableOnly
[67416.850705] 13618 pages reserved
[67416.854191] 0 pages hwpoisoned
[67416.857359] [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
[67416.865452] [  384]     0   384     5331      468      16        0         -1000 udevd
[67416.873616] [ 1730]     0  1730     2493      863       8        0             0 dhclient
[67416.882012] [ 1811]     0  1811     4748       64      15        0             0 rpcbind
[67416.890350] [ 1842]   102  1842     5841      505      17        0             0 rpc.statd
[67416.898831] [ 1856]     0  1856     6329       53      17        0             0 rpc.idmapd
[67416.907320] [ 1936]     0  1936     1254      384       8        0             0 iscsid
[67416.915539] [ 1937]     0  1937     1379      826       8        0           -17 iscsid
[67416.923756] [ 2146]     0  2146    29672      424      23        0             0 rsyslogd
[67416.932054] [ 2190]     0  2190     9120     1593      23        0             0 manage_addresse
[67416.940954] [ 2243]     0  2243     1034      368       8        0             0 acpid
[67416.949124] [ 2325]     0  2325     5100      343      16        0             0 cron
[67416.957067] [ 2392]   101  2392     8721      204      21        0             0 ntpd
[67416.965116] [ 2620]     0  2620    13068      288      27        0         -1000 sshd
[67416.973055] [ 2777]     0  2777    12339     1871      25        0             0 manage_accounts
[67416.981971] [ 2778]     0  2778     1029      352       7        0             0 startpar
[67416.990384] [ 3418]     0  3418    15305     2807      32        0          -901 supervisord
[67416.999071] [ 3436]     0  3436     4069      391      13        0             0 getty
[67417.007103] [ 3437]     0  3437     4069      368      12        0             0 getty
[67417.015183] [ 3438]     0  3438     4069      397      13        0             0 getty
[67417.023229] [ 3439]     0  3439     4069      396      11        0             0 getty
[67417.031260] [ 3440]     0  3440     4069      387      13        0             0 getty
[67417.039290] [ 3441]     0  3441     4069      395      13        0             0 getty
[67417.047328] [ 3444]     0  3444     4519      532      13        0             0 kubelet-checker
[67417.056533] [ 3508]     0  3508    66409    13782      85        0          -999 kubelet
[67417.064760] [ 4404]     0  4404    19948      603      43        0             0 sshd
[67417.072732] [ 4471]  1019  4471    23083     3663      47        0             0 sshd
[67417.080859] [ 3656]     0  3656   523933     4595      97        0          -900 docker
[67417.089114] [ 3687]     0  3687     5330      190      15        0         -1000 udevd
[67417.097252] [ 3689]     0  3689     5330      190      15        0         -1000 udevd
[67417.105374] [ 3699]     0  3699     1107      333       8        0          1000 pause
[67417.113424] [ 3722]     0  3722    50964     1733      31        0          -901 exe
[67417.121499] [ 3743]     0  3743    51237     1714      33        0          -901 exe
[67417.129359] [ 3748]     0  3748     1107      334       7        0          1000 pause
[67417.137526] [ 3759]     0  3759     1107      334       8        0          1000 pause
[67417.145649] [ 3807]     0  3807     1107      333       8        0          1000 pause
[67417.153685] [ 3809]     0  3809     8827      890      22        0          -999 dashboard
[67417.162175] [ 3831]     0  3831     1112       21       7        0          -999 sh
[67417.169965] [ 3848]     0  3848     1082       22       7        0          1000 sh
[67417.177856] [ 3857]     0  3857    26921     4834      55        0          -999 google-fluentd
[67417.186670] [ 3862]     0  3862     7917     1002      20        0          1000 kube-proxy
[67417.195285] [ 3924]     0  3924   238062    18065     112        0          -999 google-fluentd
[67417.204193] [ 3968]     0  3968    11947     2335      27        0          1000 supervisord
[67417.212762] [ 4004]     0  4004    11938     2321      29        0          1000 supervisord
[67417.221328] [ 4012]     0  4012     5443       67      15        0          1000 start.sh
[67417.229629] [ 4015]     0  4015  1116915    29179     182        0          1000 java
[67417.237597] [ 4019]     0  4019  1966259   680880    1781        0          1000 java
[67417.245554] [ 4057]     0  4057  1097333    66890     246        0          1000 java
[67417.253657] [ 4115]     0  4115   229847     3730      81        0          1000 stackdriver-col
[67417.262649] [29505]     0 29505    19949      591      43        0             0 sshd
[67417.270687] [29508]  1019 29508    20114      680      41        0             0 sshd
[67417.278800] [10127]     0 10127    13471     1755      29        0             0 manage_accounts
[67417.287734] [10175]     0 10175    15561      169      33        0             0 curl
[67417.295849] [10179]     0 10179    11502      309      27        0             0 sshd
[67417.303808] [10195]     0 10195     8273      363      21        0             0 cron
[67417.311770] [10196]     0 10196     1050       96       8        0             0 sh
[67417.319643] [10199]     0 10199     1050       17       8        0             0 gcloud
[67417.327762] [10209]     0 10209     5137      478      15        0             0 python
[67417.335893] [10260]     0 10260     8273      363      21        0             0 cron
[67417.343853] [10276]     0 10276     1050       95       8        0             0 sh
[67417.351770] [10278]     0 10278     1050       61       8        0             0 gcloud
[67417.360005] [10290]     0 10290     5137      341      15        0             0 python
[67417.368240] [10339]     0 10339     8273      356      21        0             0 cron
[67417.376200] [10351]     0 10351     1050       97       7        0             0 sh
[67417.383973] [10353]     0 10353     1050       45       8        0             0 gcloud
[67417.392101] [10370]     0 10370     5093      314      15        0             0 python
[67417.400223] [10377]     0 10377    15305     2492      32        0          -901 supervisord
[67417.408913] [10392]     0 10392     8273      364      21        0             0 cron
[67417.416983] [10398]     0 10398     1050       98       8        0             0 sh
[67417.424853] [10399]     0 10399     2694      169      10        0             0 supervisor_watc
[67417.433751] [10400]     0 10400     3505      373      11        0             0 logger
[67417.441869] [10411]     0 10411     8273      376      21        0             0 cron
[67417.449974] [10415]     0 10415     1050       93       8        0             0 sh
[67417.457748] [10416]     0 10416     2694      402      10        0             0 supervisor_watc
[67417.466644] [10417]     0 10417     3505      350      11        0             0 logger
[67417.474767] [10424]     0 10424     8273      363      21        0             0 cron
[67417.482838] [10425]     0 10425     8273      363      21        0             0 cron
[67417.490790] [10434]     0 10434     1050       82       7        0             0 sh
[67417.498584] [10435]     0 10435     1050       86       8        0             0 sh
[67417.506354] [10436]     0 10436     8273      363      21        0             0 cron
[67417.514304] [10437]     0 10437     2694       63      10        0             0 supervisor_watc
[67417.523200] [10438]     0 10438     1050      284       7        0             0 gcloud
[67417.531343] [10439]     0 10439     3505      347      12        0             0 logger
[67417.539461] [10449]     0 10449     8273      384      21        0             0 cron
[67417.547401] [10450]     0 10450     5093       55      15        0             0 python
[67417.555620] [10452]     0 10452     8273      363      21        0             0 cron
[67417.563562] [10453]     0 10453     8273      363      21        0             0 cron
[67417.571522] [10459]     0 10459     8273      369      21        0             0 cron
[67417.579502] [10460]     0 10460     8273      369      21        0             0 cron
[67417.587549] [10461]     0 10461     8273      369      21        0             0 cron
[67417.595501] [10462]     0 10462     1050       97       8        0             0 sh
[67417.603279] [10463]     0 10463     8273      353      21        0             0 cron
[67417.611220] [10464]     0 10464     2694       94      10        0             0 supervisor_watc
[67417.620116] [10465]     0 10465     3505      344      12        0             0 logger
[67417.628231] [10466]     0 10466     8273      374      21        0             0 cron
[67417.636178] [10467]     0 10467     1050       63       8        0             0 sh
[67417.643949] [10468]     0 10468     8273      365      21        0             0 cron
[67417.652026] [10469]     0 10469     2694      129      10        0             0 supervisor_watc
[67417.660941] [10470]     0 10470     3505      345      12        0             0 logger
[67417.669094] [10471]     0 10471     1050      101       8        0             0 sh
[67417.677003] [10472]     0 10472     1050       98       8        0             0 sh
[67417.684913] [10473]     0 10473     8273      365      21        0             0 cron
[67417.692971] [10474]     0 10474     8273      365      21        0             0 cron
[67417.701119] [10475]     0 10475     2694      308      10        0             0 supervisor_watc
[67417.710020] [10476]     0 10476     2694      292      10        0             0 supervisor_watc
[67417.718919] [10477]     0 10477     3505      343      12        0             0 logger
[67417.727058] [10478]     0 10478     3505      400      10        0             0 logger
[67417.735176] [10479]     0 10479     8273      364      21        0             0 cron
[67417.743123] [10480]     0 10480     1050       89       8        0             0 sh
[67417.751138] [10481]     0 10481     1050      109       8        0             0 sh
[67417.758936] [10482]     0 10482     1050       92       7        0             0 sh
[67417.766757] [10483]     0 10483     8273      364      21        0             0 cron
[67417.774813] [10484]     0 10484     1050       70       7        0             0 sh
[67417.782598] [10486]     0 10486     1050       36       8        0             0 gcloud
[67417.790816] [10487]     0 10487     2693      385      10        0             0 supervisor_watc
[67417.799884] [10488]     0 10488     3505      351      12        0             0 logger
[67417.808027] [10489]     0 10489     2693      332      10        0             0 supervisor_watc
[67417.816940] [10490]     0 10490     3505      340      12        0             0 logger
[67417.825181] [10491]     0 10491     8273      353      21        0             0 cron
[67417.833301] [10495]     0 10495     8273      366      21        0             0 cron
[67417.841245] [10496]     0 10496     2691       45      10        0             0 supervisor_watc
[67417.850261] [10497]     0 10497     3505      325      12        0             0 logger
[67417.858481] [10499]     0 10499     1050       92       8        0             0 sh
[67417.866265] [10501]     0 10501     8273      348      21        0             0 cron
[67417.874302] [10502]     0 10502     8273      325      21        0             0 cron
[67417.882357] [10503]     0 10503     2691       61       9        0             0 supervisor_watc
[67417.891256] [10504]     0 10504     3505      379      12        0             0 logger
[67417.899373] [10513]     0 10513     1050       89       8        0             0 sh
[67417.907146] [10514]     0 10514     1050       83       8        0             0 sh
[67417.914938] [10515]     0 10515     1050       75       8        0             0 sh
[67417.922717] [10516]     0 10516     8273      361      21        0             0 cron
[67417.930664] [10518]     0 10518     1050       43       7        0             0 gcloud
[67417.938786] [10519]     0 10519     2689       43      10        0             0 supervisor_watc
[67417.947902] [10520]     0 10520     3505      363      12        0             0 logger
[67417.956020] [10523]     0 10523     4999       31      12        0             0 python
[67417.964428] [10524]     0 10524     2689      354      10        0             0 supervisor_watc
[67417.973427] [10525]     0 10525     3505      349      11        0             0 logger
[67417.981543] [10526]     0 10526     8273      361      21        0             0 cron
[67417.989600] [10529]     0 10529     8273      309      21        0             0 cron
[67417.997540] [10531]     0 10531     1050       96       8        0             0 sh
[67418.005310] [10533]     0 10533     8273      309      21        0             0 cron
[67418.013253] [10534]     0 10534     1050       83       7        0             0 sh
[67418.021039] [10536]     0 10536     8275      354      21        0             0 cron
[67418.028978] [10537]     0 10537     8275      357      21        0             0 cron
[67418.036959] [10538]     0 10538     4999       31      12        0             0 python
[67418.045077] [10540]     0 10540     2679       36      10        0             0 supervisor_watc
[67418.054179] [10541]     0 10541     3505      384      12        0             0 logger
[67418.062422] [10542]     0 10542     6728      339      18        0             0 cron
[67418.070363] [10543]     0 10543     1050      263       7        0             0 supervisor
[67418.078939] [10544]     0 10544     1050      267       8        0             0 supervisor
[67418.087419] [10545]     0 10545     1050      278       8        0             0 supervisor
[67418.095898] [10546]     0 10546     1050      275       7        0             0 supervisor
[67418.104364] [10547]     0 10547     1050      273       8        0             0 supervisor
[67418.112844] [10548]     0 10548     6728      339      18        0             0 cron
[67418.120803] [10549]     0 10549     6728      339      18        0             0 cron
[67418.128751] [10550]     0 10550     8273       74      20        0             0 cron
[67418.136711] [10551]     0 10551     8273       74      20        0             0 cron
[67418.144790] [10552]     0 10552     6218      387      16        0             0 cron
[67418.152825] [10553]     0 10553     2305       15       8        0             0 supervisor_watc
[67418.162663] [10554]     0 10554     2461      353       9        0             0 logger
[67418.170801] [10560]     0 10560     5106       69      14        0             0 cron
[67418.178882] [10561]     0 10561     8273       74      20        0             0 cron
[67418.186972] [10562]     0 10562     1409      123       8        0             0 cat
[67418.194947] [10563]     0 10563     1409      117       7        0             0 cat
[67418.202821] [10564]     0 10564     1409      108       8        0             0 cat
[67418.210687] [10565]     0 10565     1409      110       8        0             0 cat
[67418.218565] [10566]     0 10566     1409      123       7        0             0 cat
[67418.226437] Out of memory: Kill process 4019 (java) score 1748 or sacrifice child
[67418.234080] Killed process 4019 (java) total-vm:7865036kB, anon-rss:2723520kB, file-rss:0kB
[67445.596207] cbr0: port 5(veth271ea24) entered disabled state
[67446.596107] cbr0: port 4(vethcfbfac8) entered disabled state
[67446.602265] cbr0: port 3(veth16de697) entered disabled state
[67449.416285] cbr0: port 5(veth271ea24) entered disabled state
[67449.424839] device veth271ea24 left promiscuous mode
[67449.430278] cbr0: port 5(veth271ea24) entered disabled state
[67449.746177] cbr0: port 3(veth16de697) entered disabled state
[67449.754717] device veth16de697 left promiscuous mode
[67449.760284] cbr0: port 3(veth16de697) entered disabled state
[67450.218212] cbr0: port 4(vethcfbfac8) entered disabled state
[67450.226545] device vethcfbfac8 left promiscuous mode
[67450.232081] cbr0: port 4(vethcfbfac8) entered disabled state
[67464.315717] aufs au_opts_verify:1570:docker[11181]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.174400] aufs au_opts_verify:1570:docker[11181]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.230039] aufs au_opts_verify:1570:docker[11183]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.250461] aufs au_opts_verify:1570:docker[11181]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.331599] aufs au_opts_verify:1570:docker[11183]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.385926] aufs au_opts_verify:1570:docker[11183]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.405053] aufs au_opts_verify:1570:docker[11183]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.419283] aufs au_opts_verify:1570:docker[11181]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.435899] device veth8e7e5f0 entered promiscuous mode
[67489.441802] IPv6: ADDRCONF(NETDEV_UP): veth8e7e5f0: link is not ready
[67489.467296] aufs au_opts_verify:1570:docker[11181]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.513411] aufs au_opts_verify:1570:docker[11230]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.555424] device veth9e77065 entered promiscuous mode
[67489.562350] IPv6: ADDRCONF(NETDEV_UP): veth9e77065: link is not ready
[67489.570258] cbr0: port 4(veth9e77065) entered forwarding state
[67489.577835] cbr0: port 4(veth9e77065) entered forwarding state
[67489.649741] IPv6: ADDRCONF(NETDEV_CHANGE): veth8e7e5f0: link becomes ready
[67489.657864] cbr0: port 3(veth8e7e5f0) entered forwarding state
[67489.665455] cbr0: port 3(veth8e7e5f0) entered forwarding state
[67489.810945] aufs au_opts_verify:1570:docker[11238]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.917402] aufs au_opts_verify:1570:docker[11286]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.931148] aufs au_opts_verify:1570:docker[11179]: dirperm1 breaks the protection by the permission bits on the lower branch
[67489.989947] aufs au_opts_verify:1570:docker[11293]: dirperm1 breaks the protection by the permission bits on the lower branch
[67490.032372] IPv6: ADDRCONF(NETDEV_CHANGE): veth9e77065: link becomes ready
[67490.116133] IPv6: eth0: IPv6 duplicate address fe80::42:aff:fe0c:102 detected!
[67490.213080] aufs au_opts_verify:1570:docker[11293]: dirperm1 breaks the protection by the permission bits on the lower branch
[67490.339618] aufs au_opts_verify:1570:docker[11179]: dirperm1 breaks the protection by the permission bits on the lower branch
[67492.226354] aufs au_opts_verify:1570:docker[11333]: dirperm1 breaks the protection by the permission bits on the lower branch
[67492.396825] aufs au_opts_verify:1570:docker[11333]: dirperm1 breaks the protection by the permission bits on the lower branch
[67492.493260] aufs au_opts_verify:1570:docker[11344]: dirperm1 breaks the protection by the permission bits on the lower branch
[67495.103886] aufs au_opts_verify:1570:docker[11405]: dirperm1 breaks the protection by the permission bits on the lower branch
[67495.836382] aufs au_opts_verify:1570:docker[11405]: dirperm1 breaks the protection by the permission bits on the lower branch
[67495.879572] aufs au_opts_verify:1570:docker[11412]: dirperm1 breaks the protection by the permission bits on the lower branch
[67497.157476] IPv4: martian source 10.12.1.1 from 10.12.1.2, on dev eth0
[67497.164322] ll header: 00000000: ff ff ff ff ff ff 02 42 0a 0c 01 02 08 06        .......B......
[67497.173349] IPv4: martian source 10.12.1.1 from 10.12.1.2, on dev eth0
[67497.180103] ll header: 00000000: ff ff ff ff ff ff 02 42 0a 0c 01 02 08 06        .......B......
[67504.604016] cbr0: port 4(veth9e77065) entered forwarding state
[67504.668023] cbr0: port 3(veth8e7e5f0) entered forwarding state

robinanil@gke-apiserver-prod-2016-03-30t18-34-34-e8673210-node-lida:~$ ps -Aef |grep docker
root     10377  3418  0 12:52 ?        00:00:00 /bin/bash /usr/sbin/docker-checker.sh
root     11047     1  1 13:19 ?        00:00:28 /usr/local/bin/kubelet --api-servers=https://104.154.23.3 --enable-debugging-handlers=true --cloud-provider=gce --config=/etc/kubernetes/manifests --allow-privileged=True --v=2 --cluster-dns=10.15.240.10 --cluster-domain=cluster.local --configure-cbr0=true --cgroup-root=/ --system-cgroups=/system --runtime-cgroups=/docker-daemon --kubelet-cgroups=/kubelet --node-labels=cloud.google.com/gke-nodepool=default-pool --babysit-daemons=true
root     11175     1  0 13:20 ?        00:00:14 /usr/bin/docker daemon -p /var/run/docker.pid --insecure-registry 10.0.0.0/8 --bridge=cbr0 --iptables=false --ip-masq=false --log-level=warn
root     11256 11175  0 13:20 ?        00:00:02 docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 6061 -container-ip 10.12.1.3 -container-port 6061
root     11266 11175  0 13:20 ?        00:00:04 docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 6060 -container-ip 10.12.1.3 -container-port 6060
1005     19693 19376  0 14:01 pts/0    00:00:00 grep docker

@dchen1107
Copy link
Member

@r-tock The issue you reported at #23556 (comment) is a totally different issue. Looks like the node is totally memory over committed here which triggers the sys oom by kernel. Are your workloads ask too small resource requests, but use too much over their initial requests with the memory?

@robin-anil
Copy link

This has not happened before. We have not specified a resource requirement and max heap size on the JVM is set at a max heap of 2G out of 3.6G on that machine. It is very unlikely JVM is going cause this system to go overcommitted as we have been running with this config for a while. In this case the kubelet restarted which makes me wonder that if one of the new addons is causing this OOM.

@robin-anil
Copy link

@dchen1107 Yes, Agreed the issue is different from the earlier ones but all points to the recent upgrade as the general root cause. I understand the usefulness of the cluster-addons. However, the pushing a release without a heads-up to production clients have left us in this state where we are unable to run our service reliably. Yes, we can peel the onion figure out the aftermath of issues one-by-one. I am all here for helping out diagnose these but wouldn't it be more prudent to rollback the release and allow us to get back into a stable state and then roll forward with right documentation about the breaking changes.

And please do clarify if this is a wrong assessment, from where I see this, this is a new release gone bad.

@robin-anil
Copy link

Unfortunately, our partners don't care about Kubernetes or containers, they are trying to run a restaurant and making sure their guests have a great experience. We have to explain to them in plain terms and explain to them why their guests are having a bad experience booking on our system. Some of these restaurants may not be able to afford a loss of conversion due to micro-outages. It's is a big thing for them. For many, this eats directly into their bottom-line

So quite simply:

  1. Are you pushing a fix?
  2. Or are you doing to rollback?

In either case, what would be the ETA?

@cjcullen
Copy link
Member

@r-tock We are cutting a 1.2.1 release this afternoon. We will begin rolling that out broadly over the next several days.

@robin-anil
Copy link

@cjcullen Thanks, I am talking with @roberthbailey offline to see what we can do to get back into a stable state immediately.

@dchen1107
Copy link
Member

@r-tock All prs required to fix your first issues are merged, and we are cutting 1.2.1 release shortly today.

On your second issue, I looked at your comment at #23556 (comment). The only newly introduced cluster-addons pod is Kube-proxy. Kube-proxy is not new, and the binary used to run as a daemon like what kubelet and docker are. In 1.2 release, we build kube-proxy as docker image and run it as static pod. Looks like that tiny overhead is introduced by kube-proxy base image, and related code is at: https://github.com/kubernetes/kubernetes/blob/master/build/common.sh#L106

cc/ @bgrant0607 @bprashanth @mikedanese

@robin-anil
Copy link

Thank you, we will help test 1.2.1 once its ready for testing.

@dchen1107 dchen1107 added priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. and removed priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. labels Mar 31, 2016
@bprashanth
Copy link
Contributor

If this is an OOM for the reason stated in #23556 (comment), simply increasing the size of the node should fix it. The increase in memory used by a debian base image vs busybox should be close to nothing, according to /sys/fs/cgroup/memory/ anyway (<10Mb).

Perhaps running kube-proxy in a container (vs raw on the node) has increased the overall footprint by some amount that puts you over the edge, it's hard to say for sure without knowing your exact free amount, but it will not grow unbounded.

This has not happened before. We have not specified a resource requirement and max heap size on the JVM is set at a max heap of 2G out of 3.6G on that machine. It is very unlikely JVM is going cause this system to go overcommitted as we have been running with this config for a while. In this case the kubelet restarted which makes me wonder that if one of the new addons is causing this OOM.

Setting resource limits/request will give you guaranteed QoS (https://github.com/kubernetes/kubernetes/blob/release-1.2/docs/proposals/resource-qos.md#qos-classes) which should give it a better OOM score (@dchen1107 correct me if I'm wrong)

Also from your kern.log, you have about 80M free:

[67416.759943] Node 0 DMA: 10*4kB (UEM) 10*8kB (UEM) 9*16kB (UEM) 7*32kB (EM) 5*64kB (UM) 3*128kB (UEM) 2*256kB (UE) 3*512kB (UEM) 1*1024kB (E) 3*2048kB (EMR) 1*4096kB (M) = 14504kB
[67416.779112] Node 0 DMA32: 1331*4kB (UEM) 744*8kB (UEM) 427*16kB (UE) 320*32kB (UEM) 189*64kB (UEM) 87*128kB (UEM) 16*256kB (UEM) 1*512kB (M) 0*1024kB 0*2048kB 1*4096kB (R) = 60284kB
[67416.798173] Node 0 Normal: 1297*4kB (UEM) 256*8kB (UEM) 52*16kB (UM) 4*32kB (UMR) 6*64kB (UMR) 2*128kB (MR) 2*256kB (R) 1*512kB (R) 1*1024kB (R) 0*2048kB 0*4096kB = 10884kB

This includes physical memory + swap. You have no swap (total swap = 0Kb).
Most of your memory is in active anon, meaning it was recently used (2890012kB+511896kB):

[67416.616615] Node 0 DMA free:14452kB min:292kB low:364kB high:436kB active_anon:716kB inactive_anon:0kB active_file:20kB inactive_file:104kB unevictable:8kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:8kB dirty:0kB writeback:0kB mapped:12kB shmem:0kB slab_reclaimable:28kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:1631 all_unreclaimable? yes
[67416.657200] lowmem_reserve[]: 0 2983 3544 3544
[67416.662441] Node 0 DMA32 free:59804kB min:56632kB low:70788kB high:84948kB active_anon:2890012kB inactive_anon:176kB active_file:3352kB inactive_file:4072kB unevictable:2848kB isolated(anon):0kB isolated(file):0kB present:3129332kB managed:3054876kB mlocked:2852kB dirty:8kB writeback:0kB mapped:4972kB shmem:764kB slab_reclaimable:17032kB slab_unreclaimable:24704kB kernel_stack:6960kB pagetables:17792kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:11434 all_unreclaimable? yes
[67416.707156] lowmem_reserve[]: 0 0 560 560
[67416.711952] Node 0 Normal free:10332kB min:10652kB low:13312kB high:15976kB active_anon:511896kB inactive_anon:28kB active_file:8kB inactive_file:12kB unevictable:596kB isolated(anon):0kB isolated(file):0kB present:628736kB managed:574264kB mlocked:596kB dirty:0kB writeback:0kB mapped:168kB shmem:132kB slab_reclaimable:4404kB slab_unreclaimable:7372kB kernel_stack:1520kB pagetables:2364kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:75 all_unreclaimable? yes

And now the interesting bit, your java and kube-proxy are at the same oom score, but you have a few java processes using more memory:

[67417.186670] [ 3862]     0  3862     7917     1002      20        0          1000 kube-proxy
[67417.195285] [ 3924]     0  3924   238062    18065     112        0          -999 google-fluentd
[67417.204193] [ 3968]     0  3968    11947     2335      27        0          1000 supervisord
[67417.212762] [ 4004]     0  4004    11938     2321      29        0          1000 supervisord
[67417.221328] [ 4012]     0  4012     5443       67      15        0          1000 start.sh
[67417.229629] [ 4015]     0  4015  1116915    29179     182        0          1000 java
[67417.237597] [ 4019]     0  4019  1966259   680880    1781        0          1000 java
[67417.245554] [ 4057]     0  4057  1097333    66890     246        0          1000 java
[67417.253657] [ 4115]     0  4115   229847     3730      81        0          1000 stackdriver-col

And the last bit shows the oom'd process memory stats:

[67418.218565] [10566]     0 10566     1409      123       7        0             0 cat
[67418.226437] Out of memory: Kill process 4019 (java) score 1748 or sacrifice child
[67418.234080] Killed process 4019 (java) total-vm:7865036kB, anon-rss:2723520kB, file-rss:0kB

I'm no oom analysis expret, just trying to be helpful.

I can't explain why this would suddenly start happening, perhaps it's because of some of the other conditions on the node, but it looks like java had the most intense memory profile from the posted kernel log.

@robin-anil
Copy link

Good insight @bprashanth appreciate it. Looks like JVMs are taking a total of 4G total VM size. Which is suspicious. But the resident size is about ~780MB, I am trying to see how that matches up.

@vishh
Copy link
Contributor

vishh commented Apr 1, 2016

Setting resource limits/request will give you guaranteed QoS (https://github.com/kubernetes/kubernetes/blob/release-1.2/docs/proposals/resource-qos.md#qos-classes) which should give it a better OOM score (@dchen1107 correct me if I'm wrong)

Setting memory limits is what is necessary to be in the Guaranteed class.

And now the interesting bit, your java and kube-proxy are at the same oom score, but you have a few java processes using more memory:

The more memory a container uses that what it had originally requested, the more likely it is to be evicted in case of system memory pressure.

But the resident size is about ~780MB, I am trying to see how that matches up.

The kernel does not use RSS to identify a victim in case of system memory pressure. It uses working set which is usually greater than RSS.

@robin-anil
Copy link

@roberthbailey
After downgrading to 1.1.8, we have been running smoothly the entire night; we had a couple of ticket launches today morning which went smooth. There were no events (in get events) and no restarts.

Looking at the RAM usage, I have to say (thanks to @bprashanth's tip) that we have not been doing a good job accounting. We have 3 JVMs running. One for ApiServer, which is at 2G, one for JMX export which is running at default JVM size which I believe is 1G and log-stash exporter which is running at max-heap of1G. Overall we have oversubscribed the node except both log-stash and JMX is running with the old version of Kubernetes. The why of how this remains stable against the previous version of Kubernetes eludes me. Before switch to 1.2.1 today, I will try to move to a node with larger RAM

Side note:
On https://cloud.google.com/container-engine/release-notes, it says that custom-types released on December 8. But I do not see any support in the flags documentation https://cloud.google.com/sdk/gcloud/reference/container/clusters/create
--custom-cpu 4 --custom--memory 5 don't seem to work.

@roberthbailey
Copy link
Contributor

Side note:
On https://cloud.google.com/container-engine/release-notes it says that custom-types was released on December 8. But I do not see any support in the flags documentation https://cloud.google.com/sdk/gcloud/reference/container/clusters/create
--custom-cpu 4 --custom--memory 5 don't seem to work.

We didn't add the --custom-cpu and --custom-memory flags to our gcloud command, but you can specify the --machine-type command passing in the value expected by the compute API (click on the API tab under the "create the instance" box on https://cloud.google.com/compute/docs/instances/creating-instance-with-custom-machine-type#create):

gcloud container clusters create NAME --machine-type custom-4-5120

will create a 3 node cluster with 4 cpu / 5 GB memory nodes.

@robin-anil
Copy link

Thanks, that is a surprising API choice but works nevertheless. New cluster is up with 5G ram and ready for upgrade to 1.2.1
apiserver-prod-2016-04-01t15-06-34

@robin-anil
Copy link

Thanks for rolling back yesterday it was a wise-move considering we just had spiky ticket launch at ~7000 page-views a minute and everything have been stable. And its wonderful to see when the whole stack works.

screen shot 2016-04-01 at 12 06 09 pm

@roberthbailey
Copy link
Contributor

@r-tock -- can we close this issue or is there further debugging that you'd like to do?

@robin-anil
Copy link

Feel free to close this. I would still like to understand the investigation if you continue to figure out what went wrong with docker-manager. Maybe a separate bug tracking it?

@roberthbailey
Copy link
Contributor

@dchen1107 do we have a bug tracking the docker issues that this exposed?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. sig/node Categorizes an issue or PR as relevant to SIG Node.
Projects
None yet
Development

No branches or pull requests

13 participants