{"action":"opened","issue":{"url":"https://api.github.com/repos/rancher/rancher/issues/2627","labels_url":"https://api.github.com/repos/rancher/rancher/issues/2627/labels{/name}","comments_url":"https://api.github.com/repos/rancher/rancher/issues/2627/comments","events_url":"https://api.github.com/repos/rancher/rancher/issues/2627/events","html_url":"https://github.com/rancher/rancher/issues/2627","id":116089741,"number":2627,"title":"Failures in health checking","user":{"login":"Rucknar","id":5539660,"avatar_url":"https://avatars.githubusercontent.com/u/5539660?v=3","gravatar_id":"","url":"https://api.github.com/users/Rucknar","html_url":"https://github.com/Rucknar","followers_url":"https://api.github.com/users/Rucknar/followers","following_url":"https://api.github.com/users/Rucknar/following{/other_user}","gists_url":"https://api.github.com/users/Rucknar/gists{/gist_id}","starred_url":"https://api.github.com/users/Rucknar/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Rucknar/subscriptions","organizations_url":"https://api.github.com/users/Rucknar/orgs","repos_url":"https://api.github.com/users/Rucknar/repos","events_url":"https://api.github.com/users/Rucknar/events{/privacy}","received_events_url":"https://api.github.com/users/Rucknar/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":0,"created_at":"2015-11-10T11:38:49Z","updated_at":"2015-11-10T11:38:49Z","closed_at":null,"body":"**Server Versions**\r\n```\r\nComponent\tVersion\r\nRancher\tv0.44.0\r\nCattle\tv0.107.0\r\nUser Interface\tv0.65.0\r\nRancher Compose\tv0.5.1\r\n```\r\n**Host Version**\r\n```\r\nRancherOS 0.4.0-RC-11\r\n```\r\n\r\n**Summary**\r\nServices are failing health checks and recycling, after some debugging it appears this could be false test failures from the health checking haproxy node. \r\n\r\n**Background**\r\nBeen looking at this with @ibuildthecloud help over the last week, in that time we've fixed a number of issues related to our container builds however the problem remained. I've come up with a repeatable (on our deployment at least) set of steps to replicate the issue. \r\n\r\n**Test Case Summary**\r\nInitiate a build of 100 containers across two hosts (physical in our case) using rancher compose. We've repeated this test with health checking enabled for ports, enabled with a full HTTP1.1 request and disabled. \r\n\r\n**Observed behaviour**\r\nService builds successfully and containers pass the initial health checks. The services go 'green' in rancher's GUI and the compose prompt returns. After a varying amount of time (generally always sub 60 minutes), a number of the containers all at once will be marked as failed. The docker logs indicates that the rancher load balancer has killed them and rancher takes measures to restore the scaling of the service. I've not found a pattern with how this happens but it occurs ~ every hour. In doing so we can in some scenarios overload docker behind the scenes which causes further issues for us. \r\n\r\n**Docker compose**\r\n```\r\nWebsiteLB:\r\n  ports:\r\n  - 3000:3000\r\n  restart: 'no'\r\n  labels:\r\n    io.rancher.scheduler.global: 'true'\r\n  tty: true\r\n  image: rancher/load-balancer-service\r\n  volumes:\r\n  - /var/log/iam:/var/tmp\r\n  links:\r\n  - 'WebServiceV1:'\r\n  stdin_open: true\r\nWebServiceV1:\r\n  restart: 'no'\r\n  labels:\r\n    io.rancher.container.hostname_override: container_name\r\n  tty: true\r\n  image: n8io/hello-world\r\n  stdin_open: true\r\n  links:\r\n  - 'WebsiteLB:'\r\n```\r\n**Rancher compose** (this one is from when we were testing port checks only).\r\n```\r\nWebsiteLB:\r\n  scale: 2\r\n  load_balancer_config:\r\n    description: Loadbalancer for website testing.\r\n    name: WebsiteLB config\r\nWebServiceV1:\r\n  health_check:\r\n    port: 3000\r\n    interval: 2000\r\n    unhealthy_threshold: 3\r\n    request_line: ''\r\n    healthy_threshold: 2\r\n    response_timeout: 2000\r\n  scale: 100\r\n```\r\n\r\n**Docker Events** (from one of two hosts):\r\n```\r\n2015-11-10T11:29:12.000000000Z f4bce0ad12b9c2eee0de9b86fead284be462ad95623d62ab22f6a27156d9024c: (from n8io/hello-world:latest) create\r\n2015-11-10T11:29:12.000000000Z f4bce0ad12b9c2eee0de9b86fead284be462ad95623d62ab22f6a27156d9024c: (from n8io/hello-world:latest) start\r\n2015-11-10T11:29:16.000000000Z 36dba964e5f16a1ce95e380bb71a6a555b24fd201f257e43312f268ed657f45d: (from n8io/hello-world:latest) create\r\n2015-11-10T11:29:17.000000000Z 36dba964e5f16a1ce95e380bb71a6a555b24fd201f257e43312f268ed657f45d: (from n8io/hello-world:latest) start\r\n2015-11-10T11:29:17.000000000Z c85ccaacbd39a50ed1f65f2a708976064b2d31cdea709f3532f81f01edb3ba9d: (from n8io/hello-world:latest) create\r\n2015-11-10T11:29:17.000000000Z c85ccaacbd39a50ed1f65f2a708976064b2d31cdea709f3532f81f01edb3ba9d: (from n8io/hello-world:latest) start\r\n2015-11-10T11:29:17.000000000Z b87d152a3ea4bacfc2a1a2aafb93090b270f08a025d9486f58f9b99946cbfa75: (from n8io/hello-world:latest) create\r\n2015-11-10T11:29:17.000000000Z b87d152a3ea4bacfc2a1a2aafb93090b270f08a025d9486f58f9b99946cbfa75: (from n8io/hello-world:latest) start\r\n2015-11-10T11:29:26.000000000Z 28dd2323f8eb77ea2c5250c42389f85998c21d0bbfefa1ee533bce0d63bd5f37: (from n8io/hello-world:latest) kill\r\n2015-11-10T11:29:29.000000000Z 3cbcba54bcd1506e788e6f145e0f12a512effb61f2f43dc02d7e6ef8bd16bbb2: (from n8io/hello-world:latest) kill\r\n2015-11-10T11:29:36.000000000Z e48783fe904eb79b6c08360d97ff495f14bbee1d60302f6d1a58950463c0b117: (from n8io/hello-world:latest) kill\r\n2015-11-10T11:29:36.000000000Z 28dd2323f8eb77ea2c5250c42389f85998c21d0bbfefa1ee533bce0d63bd5f37: (from n8io/hello-world:latest) kill\r\n2015-11-10T11:29:36.000000000Z 28dd2323f8eb77ea2c5250c42389f85998c21d0bbfefa1ee533bce0d63bd5f37: (from n8io/hello-world:latest) die\r\n2015-11-10T11:29:36.000000000Z 28dd2323f8eb77ea2c5250c42389f85998c21d0bbfefa1ee533bce0d63bd5f37: (from n8io/hello-world:latest) stop\r\n2015-11-10T11:29:39.000000000Z 3cbcba54bcd1506e788e6f145e0f12a512effb61f2f43dc02d7e6ef8bd16bbb2: (from n8io/hello-world:latest) kill\r\n2015-11-10T11:29:40.000000000Z 3cbcba54bcd1506e788e6f145e0f12a512effb61f2f43dc02d7e6ef8bd16bbb2: (from n8io/hello-world:latest) die\r\n2015-11-10T11:29:40.000000000Z 3cbcba54bcd1506e788e6f145e0f12a512effb61f2f43dc02d7e6ef8bd16bbb2: (from n8io/hello-world:latest) stop\r\n2015-11-10T11:29:46.000000000Z e48783fe904eb79b6c08360d97ff495f14bbee1d60302f6d1a58950463c0b117: (from n8io/hello-world:latest) kill\r\n2015-11-10T11:29:46.000000000Z e48783fe904eb79b6c08360d97ff495f14bbee1d60302f6d1a58950463c0b117: (from n8io/hello-world:latest) die\r\n2015-11-10T11:29:46.000000000Z e48783fe904eb79b6c08360d97ff495f14bbee1d60302f6d1a58950463c0b117: (from n8io/hello-world:latest) stop\r\n```\r\n\r\n**Haproxy Logs**:\r\n```\r\ntime=\"2015-11-10T11:28:58Z\" level=\"info\" msg=\"5687d5c9-e725-49d9-a277-2a130423f5a8_0=UP\"\r\ntime=\"2015-11-10T11:28:59Z\" level=\"info\" msg=\"cf37561c-fa93-4021-bf5c-ffac2409340a_0=UP\"\r\ntime=\"2015-11-10T11:29:00Z\" level=\"info\" msg=\"31a19ee5-9b33-40e2-9278-51834a1c242b_0=UP\"\r\ntime=\"2015-11-10T11:29:00Z\" level=\"info\" msg=\"ee7c5e02-ad95-41c8-b11c-e1e13dcf256b_0=UP\"\r\ntime=\"2015-11-10T11:29:01Z\" level=\"info\" msg=\"d6bad138-5eed-428d-9256-c6c9fe172a83_0=UP\"\r\ntime=\"2015-11-10T11:29:02Z\" level=\"info\" msg=\"f166e2f8-aee6-41f0-9243-45626dee67f0_0=UP\"\r\ntime=\"2015-11-10T11:29:03Z\" level=\"info\" msg=\"571ad227-4df1-43ff-babd-76f0611e34d1_1=UP\"\r\ntime=\"2015-11-10T11:29:03Z\" level=\"info\" msg=\"31553c25-a54b-417a-a820-5674e8cbacd5_1=UP\"\r\ntime=\"2015-11-10T11:29:04Z\" level=\"info\" msg=\"f27d4e6e-5297-4b20-9bda-4256d833177b_1=UP\"\r\ntime=\"2015-11-10T11:29:06Z\" level=\"info\" msg=\"e7510e7a-874d-4c64-a69b-6045603fd144_0=DOWN\"\r\ntime=\"2015-11-10T11:29:06Z\" level=\"info\" msg=\"f981ddea-2e6b-49ad-8637-0113c774d4a6_0=DOWN\"\r\ntime=\"2015-11-10T11:29:06Z\" level=\"info\" msg=\"f972ac4a-ff20-4568-a1de-d58a89dfb45b_0=DOWN\"\r\ntime=\"2015-11-10T11:29:06Z\" level=\"info\" msg=\"Monitoring 53 backends\"\r\ntime=\"2015-11-10T11:29:07Z\" level=\"info\" msg=\"a21e8980-9b8f-4c5d-821f-bf34b2db8f3d_0=DOWN\"\r\ntime=\"2015-11-10T11:29:12Z\" level=\"info\" msg=\"Monitoring 55 backends\"\r\ntime=\"2015-11-10T11:29:17Z\" level=\"info\" msg=\"23c224cb-f77d-42a9-acf8-46750154511c_0=DOWN\"\r\ntime=\"2015-11-10T11:29:17Z\" level=\"info\" msg=\"3695b608-6224-4b16-bebd-5f0a4c011f4c_0=DOWN\"\r\ntime=\"2015-11-10T11:29:19Z\" level=\"info\" msg=\"e7510e7a-874d-4c64-a69b-6045603fd144_0=DOWN 1/2\"\r\ntime=\"2015-11-10T11:29:19Z\" level=\"info\" msg=\"f972ac4a-ff20-4568-a1de-d58a89dfb45b_0=DOWN 1/2\"\r\ntime=\"2015-11-10T11:29:20Z\" level=\"info\" msg=\"3695b608-6224-4b16-bebd-5f0a4c011f4c_0=DOWN 1/2\"\r\ntime=\"2015-11-10T11:29:22Z\" level=\"info\" msg=\"e7510e7a-874d-4c64-a69b-6045603fd144_0=INIT\"\r\ntime=\"2015-11-10T11:29:22Z\" level=\"info\" msg=\"f981ddea-2e6b-49ad-8637-0113c774d4a6_0=INIT\"\r\ntime=\"2015-11-10T11:29:22Z\" level=\"info\" msg=\"f972ac4a-ff20-4568-a1de-d58a89dfb45b_0=INIT\"\r\ntime=\"2015-11-10T11:29:23Z\" level=\"info\" msg=\"a21e8980-9b8f-4c5d-821f-bf34b2db8f3d_0=INIT\"\r\ntime=\"2015-11-10T11:29:23Z\" level=\"info\" msg=\"23c224cb-f77d-42a9-acf8-46750154511c_0=INIT\"\r\ntime=\"2015-11-10T11:29:24Z\" level=\"info\" msg=\"3695b608-6224-4b16-bebd-5f0a4c011f4c_0=INIT\"\r\ntime=\"2015-11-10T11:29:26Z\" level=\"info\" msg=\"e7510e7a-874d-4c64-a69b-6045603fd144_0=UP\"\r\ntime=\"2015-11-10T11:29:26Z\" level=\"info\" msg=\"f981ddea-2e6b-49ad-8637-0113c774d4a6_0=UP\"\r\ntime=\"2015-11-10T11:29:26Z\" level=\"info\" msg=\"f972ac4a-ff20-4568-a1de-d58a89dfb45b_0=UP\"\r\ntime=\"2015-11-10T11:29:26Z\" level=\"info\" msg=\"a21e8980-9b8f-4c5d-821f-bf34b2db8f3d_0=UP\"\r\ntime=\"2015-11-10T11:29:26Z\" level=\"info\" msg=\"23c224cb-f77d-42a9-acf8-46750154511c_0=UP\"\r\ntime=\"2015-11-10T11:29:26Z\" level=\"info\" msg=\"3695b608-6224-4b16-bebd-5f0a4c011f4c_0=UP\"\r\n```\r\n**Rancher Server logs**\r\nNot posted as it's just lots of logs about DB records changing\r\n\r\n**Cattle logs**\r\n```\r\n2015-11-10 11:34:31,828 INFO  [:] [] [] [] [cutorService-18] [i.c.p.a.s.s.impl.AgentServiceImpl   ] Timeout waiting for response to [config.update] id [7e8da12a-c3af-427b-a2b9-56c08d55501a]\r\n2015-11-10 11:34:31,828 INFO  [:] [] [] [] [cutorService-18] [i.c.p.a.s.s.impl.AgentServiceImpl   ] Timeout waiting for response to [config.update] id [5797951f-1671-4edb-aadb-99a027d63494]\r\n2015-11-10 11:34:31,828 INFO  [:] [] [] [] [cutorService-18] [i.c.p.a.s.s.impl.AgentServiceImpl   ] Timeout waiting for response to [delegate.request] id [9e148053-da6c-495a-be20-e3c37bb2a92e]\r\n2015-11-10 11:34:31,828 INFO  [:] [] [] [] [cutorService-18] [i.c.p.a.s.s.impl.AgentServiceImpl   ] Timeout waiting for response to [ping] id [00ba6e77-6288-4b73-81f4-fd9d9c0d9f8b]\r\n2015-11-10 11:34:31,836 INFO  [:] [] [] [] [ecutorService-1] [.p.c.v.i.ConfigItemStatusManagerImpl] Timeout updating item(s) [healthcheck, ipsec-hosts, hosts, iptables] on [agent:56]\r\n2015-11-10 11:34:31,836 INFO  [:] [] [] [] [ecutorService-1] [.p.c.v.i.ConfigItemStatusManagerImpl] Timeout updating item(s) [healthcheck, ipsec-hosts, hosts, iptables] on [agent:56]\r\n2015-11-10 11:34:31,843 INFO  [:] [] [] [] [ecutorService-1] [.p.c.v.i.ConfigItemStatusManagerImpl] Timeout updating item(s) [host-routes] on [agent:53]\r\n2015-11-10 11:34:31,843 INFO  [:] [] [] [] [ecutorService-1] [.p.c.v.i.ConfigItemStatusManagerImpl] Timeout updating item(s) [host-routes] on [agent:53]\r\n```\r\n\r\n**Variations**\r\n- We used this with HTTP1.1 checking initially as that matches our current stack.\r\n- This happens with our own image, tutum/hello-world & this node based test container.\r\n\r\n**Considerations**\r\n- We've upgraded rancher a number of times, DB mapped in from the host.\r\n- Our cattle logs show a concerning amount of timeout errors\r\n- We've tested connectivity between Rancher Server and the Host / Healthcheck agent and the Container.We've not managed to find any packet loss or connectivity issues. \r\n- Rancher server lives on a VM running on a separate host. "}}