kiam server HA. Context deadline exceeded while rotating servers.

[max-lobur]

In my test AWS lab I run 3 masters with KIAM servers (quay.io/uswitch/kiam:v3.0) and 6 nodes with KIAM agents (same images). I'm getting these

{"addr":"100.112.154.80:56850","level":"error","method":"GET","msg":"error processing request: rpc error: code = DeadlineExceeded desc = context deadline exceeded","path":"/latest/meta-data/iam/security-credentials/","status":500,"time":"2019-02-18T16:48:17Z"}

every time I'm rotating masters. The error starts to appear on every one of 6 agents, once I remove at least 1 master. To stop it I need to restart all agents, when they restart they start to work normally. This does not happen if I rotate kiam server itself (delete the pod), only when I rotate the whole master instance.

I'm using this chart https://github.com/helm/charts/tree/master/stable/kiam to run kiam. No special tuning, except for I'm setting gatewayTimeoutCreation: 500ms on both agent and server.

Am I missing smth important in docs, some flag? Please suggest

[complex64]

Same issue here, KIAM v.3.2

[MilanDasek]

similar issue, kiam v3.3

[mehstg]

Just been burned by this myself - v3.2

[mseiwald]

Same issue for us on kiam v3.0

[Joseph-Irving]

We run Kiam in relatively large clusters and we regularly terminate our master nodes (we don't allow them to live longer than 7 days) and we've never seen this behaviour.

Kiam should be using a service with clusterIP: none this is so that the agents can use grpc loadbalancing, they go and discover the pod ips of each kiam-server and will loadbalance between them, if one goes down it will just try another. So I'm very puzzled as to how you're seeing this.

I'd be interested to know what networking stack you're using, incase there's some commonality there which could be what's causing this behaviour.

[mehstg]

We are using the amazon-k8s-cni plugin for networking. No other service mesh/network policy currently.

[denispesikov]

Same here
error processing request: error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded
KIAM v3.2
Any workaround?

[max-lobur]

Using calico over aws ec2.
Also using this chart to deploy https://github.com/helm/charts/tree/master/stable/kiam
It seems that it uses proper service as you mentioned https://github.com/helm/charts/blob/master/stable/kiam/templates/server-service.yaml#L26

[mehstg]

Ok. So I have been doing some more testing of this issue.

From inside a pod, when I run a cURL to request the credentials from the metadata service, it works fine before killing a KIAM server, as expected:
curl http://169.254.169.254/latest/meta-data/iam/security-credentials/dev-eu-west-1-dev01-pod-api {"Code":"Success","Type":"AWS-HMAC","AccessKeyId":"ASIAYXSSZXR7IBB2RQMP","SecretAccessKey":"O3h+vJPsu8vhWtyWOCkiV9rwh4F/3HMF+jHpMpCP","Token":"FQoGZXIvYXdzEDkaDIL6Kpd6o56IKCaqdyLtAXPxNnhIs6lvNrJwANlEupVSSwGqUzOxOhry10nANFU5VB28YPNc8BYnSy6B8+tMkw10d9ubPwfFj63sdGpuHAS+4wtrpPRbb5p2ma/qvyUu8p33t9+NGZ6BNGYUga43E9+erGSHjDuvD9I4Lwjcz831D3lAYidCAjb99Q+iOWMyScklGfH3YELKGpEtzg55KYPTH16xc+QtOUtdmcUZZsbGnvw04zb6gxhctUCneknWY9+ZfiIGRU2pXvUlavGPCtekyrTp4DnCN2IbDQnmNCfwsZfG0LZZ1yQw41FuZ3igPzzb6TM6a6LlU9gM+Cj4/oTqBQ==","Expiration":"2019-07-31T07:27:56Z","LastUpdated":"2019-07-31T07:12:56Z"}

As soon as I kill a KIAM server, the same cURL command fails immediately:
curl http://169.254.169.254/latest/meta-data/iam/security-credentials/dev-eu-west-1-dev01-pod-api error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I can then repeatedly cURL the same request and sometimes it returns OK, sometimes it fails.

The matching log line from the KIAM agent shows similar information:
{"addr":"10.1.113.124:49850","level":"error","method":"HEAD","msg":"error processing request: error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded","path":"/latest/meta-data/iam/security-credentials/dev-eu-west-1-dev01-pod-api","status":500,"time":"2019-07-31T07:22:00Z"}`

I ran a nslookup from inside a pod at the point of killing the KIAM server too. The record for the killed KIAM server disappears almost instantaneously. (For reference, we are using CoreDNS) .

It feels very much like something is being cached on the KIAM agents in relation to the IP addresses available to gRPC load balance with. DNS is very quickly removing the retired IP from the pool, but it feels like the KIAM agent is still trying to route requests to it.

The access key/secret/token above is nonsensical, it is just an example

[rhysemmas]

I am struggling to reproduce the issue myself - when killing Kiam servers in various different ways, the Kiam agent is correctly load balancing between the remaining Kiam servers.

In order to observe the agent's behaviour, I set the following env vars in the agent pod to increase the log verbosity of grpc:

GRPC_GO_LOG_SEVERITY_LEVEL=info
GRPC_GO_LOG_VERBOSITY_LEVEL=8

The following events occur on 1 agent that load balances between 2 different servers:

The agent starts up and performs some service discovery to find the servers:

INFO: 2019/08/15 14:01:25 parsed scheme: "dns"
INFO: 2019/08/15 14:01:25 ccResolverWrapper: got new service config:
INFO: 2019/08/15 14:01:25 ccResolverWrapper: sending new addresses to cc: [{10.244.2.2:443 1 10-244-2-2.kiam-server.kube-system.svc.cluster.local. <nil>} {10.244.1.3:443 1 10-244-1-3.kiam-server.kube-system.svc.cluster.local. <nil>} {10.244.1.3:443 0  <nil>} {10.244.2.2:443 0  <nil>}]

The agent connects to the servers successfully (below) - note that each server is associated with a hex value, in this instance we have the following 2 servers:
10.244.1.3 - 0xc4203c1d40
10.244.2.2 - 0xc4203c1d60

INFO: 2019/08/15 14:01:25 base.baseBalancer: got new ClientConn state:  {{[{10.244.1.3:443 0  <nil>} {10.244.2.2:443 0  <nil>}] <nil>} <nil>}
INFO: 2019/08/15 14:01:25 base.baseBalancer: handle SubConn state change: 0xc4203c1d40, CONNECTING
INFO: 2019/08/15 14:01:25 base.baseBalancer: handle SubConn state change: 0xc4203c1d60, CONNECTING
INFO: 2019/08/15 14:01:25 base.baseBalancer: handle SubConn state change: 0xc4203c1d60, READY
INFO: 2019/08/15 14:01:25 roundrobinPicker: newPicker called with readySCs: map[{10.244.2.2:443 0  <nil>}:0xc4203c1d60]

^ here, one of the grpc connections becomes ready before the other and the 'roundrobinPicker' lists this as the only server available in its pool to load balance with.

INFO: 2019/08/15 14:01:25 base.baseBalancer: handle SubConn state change: 0xc4203c1d40, READY
INFO: 2019/08/15 14:01:25 roundrobinPicker: newPicker called with readySCs: map[{10.244.1.3:443 0  <nil>}:0xc4203c1d40 {10.244.2.2:443 0  <nil>}:0xc4203c1d60]

^ the other connection becomes ready and the load balancing pool is updated to include the second server.

At this point, I kill one of the Kiam servers (10.244.1.3 - 0xc4203c1d40):

INFO: 2019/08/15 14:15:32 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
INFO: 2019/08/15 14:15:32 base.baseBalancer: handle SubConn state change: 0xc4203c1d40, CONNECTING
WARNING: 2019/08/15 14:15:32 grpc: addrConn.createTransport failed to connect to {10.244.1.3:443 0  <nil>}. Err :connection error: desc = "transport: Error while dialing dial tcp 10.244.1.3:443: connect: connection refused". Reconnecting...`

^ the agent attempts to reconnect to the server I killed. The agent will continue to try and re-connect with the server that has gone away over time (I have omitted these logs)

INFO: 2019/08/15 14:15:32 roundrobinPicker: newPicker called with readySCs: map[{10.244.2.2:443 0  <nil>}:0xc4203c1d60]

^ immediately after the connection error, the pool of servers to load balance with is updated to just include the 1 remaining server.

Throughout this, my curls from another pod to the meta-data API have been successful - there hasn't been any sign of the issue reported (these curls will also show in the agent logs but have been omitted above for clarity).

Would somebody be able to set the grpc log level env vars mentioned above in their agent deployments and provide agent logs? Including examples of agent startup and when a server is killed, so we can compare. Thanks.

[mehstg]

Hi. I have collected logs as requested.

Kiam Agent startup logs:

`{"level":"info","msg":"configuring iptables","time":"2019-08-16T12:47:59Z"}
{"level":"info","msg":"started prometheus metric listener 0.0.0.0:9620","time":"2019-08-16T12:47:59Z"}
INFO: 2019/08/16 12:47:59 parsed scheme: "dns"
INFO: 2019/08/16 12:47:59 ccResolverWrapper: got new service config: 
INFO: 2019/08/16 12:47:59 ccResolverWrapper: sending new addresses to cc: [{10.2.81.71:443 1 10-2-81-71.kiam-server.iam-proxy.svc.cluster.local. <nil>} {10.2.118.49:443 1 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local. <nil>} {10.2.118.49:443 0  <nil>} {10.2.81.71:443 0  <nil>}]
INFO: 2019/08/16 12:47:59 base.baseBalancer: got new resolved addresses:  [{10.2.81.71:443 1 10-2-81-71.kiam-server.iam-proxy.svc.cluster.local. <nil>} {10.2.118.49:443 1 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local. <nil>} {10.2.118.49:443 0  <nil>} {10.2.81.71:443 0  <nil>}]
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc4201891a0, CONNECTING
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc4201891c0, CONNECTING
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc4201891e0, CONNECTING
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc420189210, CONNECTING
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc4201891c0, READY
INFO: 2019/08/16 12:47:59 roundrobinPicker: newPicker called with readySCs: map[{10.2.118.49:443 1 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local. <nil>}:0xc4201891c0]
{"level":"info","msg":"listening :8181","time":"2019-08-16T12:47:59Z"}
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc4201891e0, READY
INFO: 2019/08/16 12:47:59 roundrobinPicker: newPicker called with readySCs: map[{10.2.118.49:443 1 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local. <nil>}:0xc4201891c0 {10.2.118.49:443 0  <nil>}:0xc4201891e0]
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc420189210, READY
INFO: 2019/08/16 12:47:59 roundrobinPicker: newPicker called with readySCs: map[{10.2.118.49:443 1 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local. <nil>}:0xc4201891c0 {10.2.118.49:443 0  <nil>}:0xc4201891e0 {10.2.81.71:443 0  <nil>}:0xc420189210]
INFO: 2019/08/16 12:47:59 base.baseBalancer: handle SubConn state change: 0xc4201891a0, READY
INFO: 2019/08/16 12:47:59 roundrobinPicker: newPicker called with readySCs: map[{10.2.81.71:443 1 10-2-81-71.kiam-server.iam-proxy.svc.cluster.local. <nil>}:0xc4201891a0 {10.2.118.49:443 1 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local. <nil>}:0xc4201891c0 {10.2.118.49:443 0  <nil>}:0xc4201891e0 {10.2.81.71:443 0  <nil>}:0xc420189210]
{"addr":"10.2.45.198:41134","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:03Z"}
{"addr":"10.2.45.198:41172","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:06Z"}
{"addr":"10.2.45.198:41188","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:09Z"}
{"addr":"10.2.45.198:41198","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:12Z"}
{"addr":"10.2.45.198:41240","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:15Z"}
{"addr":"10.2.45.198:41264","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:18Z"}
{"addr":"10.2.45.198:41276","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:21Z"}
{"addr":"10.2.45.198:41310","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:24Z"}
{"addr":"10.2.45.198:41336","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:27Z"}
{"addr":"10.2.45.198:41348","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:48:30Z"}`

We have two KIAM servers running,
1 10-2-81-71.kiam-server.iam-proxy.svc.cluster.local 10-2-118-49.kiam-server.iam-proxy.svc.cluster.local
If I run a curl from one of my containers, it works successfully:

`root@channel-service-588c949b66-tvxrr:/opt/app# curl http://169.254.169.254/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service
{"Code":"Success","Type":"AWS-HMAC","AccessKeyId":"redacted","SecretAccessKey":"redacted","Token":"redacted","Expiration":"2019-08-16T13:19:47Z","LastUpdated":"2019-08-16T13:04:47Z"}`

I then kill the EC2 host running one of the KIAM servers (10-2-118-49.kiam-server.iam-proxy.svc.cluster.local), these are specific worker nodes that only run the KIAM servers.
Almost immediately the curl begins to fail:

`root@channel-service-588c949b66-tvxrr:/opt/app# curl http://169.254.169.254/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service
error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded`

The KIAM agent logs during this period are as follows:

`{"addr":"10.2.39.230:52366","level":"error","method":"GET","msg":"error processing request: error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:50:52Z"}
{"addr":"10.2.39.230:52366","duration":5000,"headers":{"Content-Type":["text/plain; charset=utf-8"],"X-Content-Type-Options":["nosniff"]},"level":"info","method":"GET","msg":"processed request","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:50:52Z"}
{"addr":"10.2.45.198:42582","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:50:54Z"}
{"addr":"10.2.39.230:52422","level":"error","method":"GET","msg":"error processing request: error fetching credentials: rpc error: code = Canceled desc = context canceled","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:50:56Z"}
{"addr":"10.2.39.230:52422","duration":2407,"headers":{"Content-Type":["text/plain; charset=utf-8"],"X-Content-Type-Options":["nosniff"]},"level":"info","method":"GET","msg":"processed request","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:50:56Z"}
{"addr":"10.2.45.198:42612","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:50:57Z"}
{"addr":"10.2.45.198:42620","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:00Z"}
{"addr":"10.2.39.230:52466","duration":2,"headers":{"Content-Type":["application/json"]},"level":"debug","method":"GET","msg":"processed request","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":200,"time":"2019-08-16T12:51:01Z"}
{"addr":"10.2.45.198:42650","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:03Z"}
{"addr":"10.2.39.230:52488","duration":1,"headers":{"Content-Type":["application/json"]},"level":"debug","method":"GET","msg":"processed request","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":200,"time":"2019-08-16T12:51:03Z"}
{"addr":"10.2.45.198:42688","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:06Z"}
{"addr":"10.2.39.230:52504","level":"error","method":"GET","msg":"error processing request: error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:51:09Z"}
{"addr":"10.2.39.230:52504","duration":5000,"headers":{"Content-Type":["text/plain; charset=utf-8"],"X-Content-Type-Options":["nosniff"]},"level":"info","method":"GET","msg":"processed request","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:51:09Z"}
{"addr":"10.2.45.198:42700","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:09Z"}
{"addr":"10.2.45.198:42710","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:12Z"}
{"addr":"10.2.45.198:42748","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:15Z"}
{"addr":"10.2.45.198:42772","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:18Z"}
{"addr":"10.2.45.198:42790","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:21Z"}
{"addr":"10.2.39.230:52602","level":"error","method":"GET","msg":"error processing request: error fetching credentials: rpc error: code = DeadlineExceeded desc = context deadline exceeded","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:51:21Z"}
{"addr":"10.2.39.230:52602","duration":5000,"headers":{"Content-Type":["text/plain; charset=utf-8"],"X-Content-Type-Options":["nosniff"]},"level":"info","method":"GET","msg":"processed request","path":"/latest/meta-data/iam/security-credentials/stage-eu-west-1-stage01-pod-connectt-api-channel-service","status":500,"time":"2019-08-16T12:51:21Z"}
{"addr":"10.2.45.198:42824","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:24Z"}
{"addr":"10.2.45.198:42850","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:27Z"}
{"addr":"10.2.45.198:42858","duration":0,"headers":{},"level":"debug","method":"GET","msg":"processed request","path":"/ping","status":200,"time":"2019-08-16T12:51:30Z"}
`

[rhysemmas]

Hi @mehstg - thanks for providing those logs. It is strange that you aren't seeing any gRPC logs (the INFO and WARNING events) in the agent logs after killing the kiam server - are there definitely none of these entries in the agent logs when the cURLs begin to fail?

[mehstg]

No unfortunately not. I just tested again and I only really see the info messages during startup.

[rhysemmas]

OK - thanks for double checking. A few questions:

The IP addresses that are resolved in your logs above, are these the same as your kiam server pod IPs?
Could you confirm what your cpu and memory resource requests/limits are for the agent pods?
Are you also using the helm chart to deploy kiam?

Also, could you please try running kiam v3.4 (released today), as this includes some gRPC updates, and let us know if this changes any behaviour.