Router fails to get endpoints during e2e

[smarterclayton]

https://ci.openshift.redhat.com/jenkins/job/merge_pull_requests_origin/5537/

Happening fairly frequently

There was no error output from the command.
[INFO] Back to 'default' project with 'admin' user...
Running test/end-to-end/core.sh:286: executing 'oc project default/172-18-4-219:8443/system:admin' expecting success...
SUCCESS after 0.140s: test/end-to-end/core.sh:286: executing 'oc project default/172-18-4-219:8443/system:admin' expecting success
Standard output from the command:
Now using project "default" from context named "default/172-18-4-219:8443/system:admin" on server "https://172.18.4.219:8443".
There was no error output from the command.
Running test/end-to-end/core.sh:290: executing 'oc get endpoints router --output-version=v1beta3 --template='{{ if .subsets }}{{ len .subsets }}{{ else }}0{{ end }}'' expecting any result and text '[1-9]+'; re-trying every 0.2s until completion or 300.000s...
FAILURE after 299.580s: test/end-to-end/core.sh:290: executing 'oc get endpoints router --output-version=v1beta3 --template='{{ if .subsets }}{{ len .subsets }}{{ else }}0{{ end }}'' expecting any result and text '[1-9]+'; re-trying every 0.2s until completion or 300.000s: the command timed out
There was no output from the command.
There was no error output from the command.

[smarterclayton]

Early in the run:

Using project "default".
There was no error output from the command.
Running test/end-to-end/core.sh:108: executing 'oc whoami' expecting success and text 'e2e-user'...
SUCCESS after 0.095s: test/end-to-end/core.sh:108: executing 'oc whoami' expecting success and text 'e2e-user'
Standard output from the command:
e2e-user
There was no error output from the command.
Running test/end-to-end/core.sh:111: executing 'oc status -n default' expecting success...
SUCCESS after 0.252s: test/end-to-end/core.sh:111: executing 'oc status -n default' expecting success
Standard output from the command:
In project default on server https://172.18.4.219:8443

svc/docker-registry - 172.30.48.168:5000
  dc/docker-registry deploys docker.io/openshift/origin-docker-registry:53ac3df 
    deployment #1 deployed 53 seconds ago - 1 pod

svc/kubernetes - 172.30.0.1 ports 443, 53, 53

svc/router - 172.30.18.235 ports 80, 443, 1936
  dc/router deploys docker.io/openshift/origin-haproxy-router:53ac3df 
    deployment #2 deployed 53 seconds ago - 0 pods
    deployment #1 failed 53 seconds ago: cancelled as a newer deployment was found running - 1 pod

I0407 17:38:27.261965    4763 prober.go:104] Liveness probe for "router-1-0nvm4_default(52d2f7a7-fce7-11e5-b5a6-0e870c302687):router" failed (failure): Get http://localhost:1936/healthz: dial tcp [::1]:1936: getsockopt: connection refused
I0407 17:38:27.262359    4763 server.go:606] Event(api.ObjectReference{Kind:"Pod", Namespace:"default", Name:"router-1-0nvm4", UID:"52d2f7a7-fce7-11e5-b5a6-0e870c302687", APIVersion:"v1", ResourceVersion:"607", FieldPath:"spec.containers{router}"}): typ
e: 'Warning' reason: 'Unhealthy' Liveness probe failed: Get http://localhost:1936/healthz: dial tcp [::1]:1936: getsockopt: connection refused
I0407 17:38:27.262463    4763 prober.go:104] Readiness probe for "router-1-0nvm4_default(52d2f7a7-fce7-11e5-b5a6-0e870c302687):router" failed (failure): Get http://localhost:1936/healthz: dial tcp [::1]:1936: getsockopt: connection refused
I0407 17:38:27.262497    4763 server.go:606] Event(api.ObjectReference{Kind:"Pod", Namespace:"default", Name:"router-1-0nvm4", UID:"52d2f7a7-fce7-11e5-b5a6-0e870c302687", APIVersion:"v1", ResourceVersion:"607", FieldPath:"spec.containers{router}"}): typ
e: 'Warning' reason: 'Unhealthy' Readiness probe failed: Get http://localhost:1936/healthz: dial tcp [::1]:1936: getsockopt: connection refused
I0407 17:38:28.005261    4763 manager.go:1400] Container "a97340019c2b7329c7a8ecbe7f65407b7838b4fe72657b3f6e3eefdfa763d707 router default/router-1-0nvm4" exited after 929.656383ms
I0407 17:38:28.005746    4763 server.go:606] Event(api.ObjectReference{Kind:"Pod", Namespace:"default", Name:"router-1-0nvm4", UID:"52d2f7a7-fce7-11e5-b5a6-0e870c302687", APIVersion:"v1", ResourceVersion:"607", FieldPath:"spec.containers{router}"}): typ
e: 'Normal' reason: 'Killing' Killing container with docker id a97340019c2b: Need to kill pod.
I0407 17:38:28.322312    4763 manager.go:1368] Killing container "32fa2c8be13a0c35bf120ba21264667bd75e5dbc29035a55dcb552e656457c3f default/router-1-0nvm4" with 30 second grace period
I0407 17:38:28.540623    4763 helpers.go:101] Unable to get network stats from pid 12216: couldn't read network stats: failure opening /rootfs/proc/12216/net/dev: open /rootfs/proc/12216/net/dev: no such file or directory
I0407 17:38:28.691022    4763 generic.go:138] GenericPLEG: 52d2f7a7-fce7-11e5-b5a6-0e870c302687/a97340019c2b7329c7a8ecbe7f65407b7838b4fe72657b3f6e3eefdfa763d707: running -> exited
I0407 17:38:28.751013    4763 manager.go:855] Destroyed container: "/system.slice/docker-32fa2c8be13a0c35bf120ba21264667bd75e5dbc29035a55dcb552e656457c3f.scope" (aliases: [k8s_POD.fe97dd62_router-1-0nvm4_default_52d2f7a7-fce7-11e5-b5a6-0e870c302687_e892
7fd6 32fa2c8be13a0c35bf120ba21264667bd75e5dbc29035a55dcb552e656457c3f], namespace: "docker")
I0407 17:38:28.751104    4763 handler.go:320] Added event &{/system.slice/docker-32fa2c8be13a0c35bf120ba21264667bd75e5dbc29035a55dcb552e656457c3f.scope 2016-04-07 17:38:28.751090997 +0000 UTC containerDeletion {<nil>}}
I0407 17:38:28.931523    4763 manager.go:1400] Container "32fa2c8be13a0c35bf120ba21264667bd75e5dbc29035a55dcb552e656457c3f default/router-1-0nvm4" exited after 609.176107ms

@Kargakis @ironcladlou should this happen in e2e? Getting two deployments of the router?

[smarterclayton]

NM, that's because of how the router install works. It's triggering a reload by changing the env for the syn eater.

[smarterclayton]

This seems wrong:

I0407 17:36:47.737760    4763 factory.go:272] About to try and schedule pod router-2-kna27
...
I0407 17:36:56.208057    4763 factory.go:272] About to try and schedule pod router-1-0nvm4

[smarterclayton]

I0407 17:36:33.449502    4763 factory.go:272] About to try and schedule pod router-1-deploy
I0407 17:36:33.744055    4763 factory.go:272] About to try and schedule pod router-2-deploy
I0407 17:36:34.531094    4763 factory.go:272] About to try and schedule pod router-1-deploy
I0407 17:36:34.748442    4763 factory.go:272] About to try and schedule pod router-2-deploy
I0407 17:36:36.534555    4763 factory.go:272] About to try and schedule pod router-1-deploy
I0407 17:36:36.752137    4763 factory.go:272] About to try and schedule pod router-2-deploy
I0407 17:36:40.537860    4763 factory.go:272] About to try and schedule pod router-1-deploy
I0407 17:36:40.758626    4763 factory.go:272] About to try and schedule pod router-2-deploy
I0407 17:36:47.737760    4763 factory.go:272] About to try and schedule pod router-2-kna27
I0407 17:36:56.208057    4763 factory.go:272] About to try and schedule pod router-1-0nvm4
I0407 17:36:57.211333    4763 factory.go:272] About to try and schedule pod router-1-0nvm4
I0407 17:36:59.214447    4763 factory.go:272] About to try and schedule pod router-1-0nvm4
I0407 17:37:03.217359    4763 factory.go:272] About to try and schedule pod router-1-0nvm4
I0407 17:37:05.825139    4763 kubelet.go:2430] SyncLoop (PLEG): "router-2-deploy_default(456e572f-fce7-11e5-b5a6-0e870c302687)", event: &pleg.PodLifecycleEvent{ID:"456e572f-fce7-11e5-b5a6-0e870c302687", Type:"ContainerStarted", Data:"1f02c778a6f5825547b
I0407 17:37:06.354535    4763 kubelet.go:2430] SyncLoop (PLEG): "router-1-deploy_default(45435414-fce7-11e5-b5a6-0e870c302687)", event: &pleg.PodLifecycleEvent{ID:"45435414-fce7-11e5-b5a6-0e870c302687", Type:"ContainerStarted", Data:"03befa80c633bc4a41b
I0407 17:37:11.225722    4763 factory.go:272] About to try and schedule pod router-1-0nvm4
I0407 17:37:12.443523    4763 kubelet.go:2430] SyncLoop (PLEG): "router-2-deploy_default(456e572f-fce7-11e5-b5a6-0e870c302687)", event: &pleg.PodLifecycleEvent{ID:"456e572f-fce7-11e5-b5a6-0e870c302687", Type:"ContainerDied", Data:"d41e3a850987f70cdf9db6
I0407 17:37:27.229644    4763 factory.go:272] About to try and schedule pod router-1-0nvm4
I0407 17:37:49.132053    4763 kubelet.go:2430] SyncLoop (PLEG): "router-1-deploy_default(45435414-fce7-11e5-b5a6-0e870c302687)", event: &pleg.PodLifecycleEvent{ID:"45435414-fce7-11e5-b5a6-0e870c302687", Type:"ContainerDied",

[smarterclayton]

So it looks like we schedule both deployment pods. The second one? starts running, and creates at least one pod in the second group. It scales up, then for some reason gets scaled down (failed, death?) at

I0407 17:36:54.011987    4763 replication_controller.go:451] Too many "default"/"router-2" replicas, need 0, deleting 1

It is incredibly worrying to me that we don't see the logs of the failed pods - it may be because they were empty, but not seeing how the deployment logs would be empty at all.

[smarterclayton]

Looks like we had two deployment pods running at the same time. That shouldn't be happening?

[smarterclayton]

Moving this to @pweil-'s team for triage

[smarterclayton]

deployment-failure-logs-20160407.zip