I am observing weird intermittent timeouts on HTTP calls from a pod on k8s. The pod is running a java program and doing HTTP calls out to other nodes and even back into itself on its local IP. We go through periods of about 5-10min at a time several times a day where some of these HTTP calls get a timeout even though the remote server being called is available. In these time windows the timeouts come and go irrespective of whether the HTTP call is to other pods or even back into its own local IP.

To illustrate the issue, here is a log file of 3 http calls and associated packet capture done with tcpdump on the node:

Call 1 - success
2020/03/10 22:38:24.471 FINE    [jg-es-1][guru.jini.arch.impl.other.HttpImpl.doHttpMethodReactive] # Sending [GET] request to [http://100.96.26.24:8080] --
2020/03/10 22:38:24.475 FINE    [jg-async-http-3-4][guru.jini.arch.impl.rest.JaxRsResponse.<init>] # Response to [GET] on [http://100.96.26.24:8080] with RequestId [4545818456] after [3.307892]ms --
2 seconds later... Call 2 - fail
2020/03/10 22:38:26.471 FINE    [jg-es-1][guru.jini.arch.impl.other.HttpImpl.doHttpMethodReactive] # Sending [GET] request to [http://100.96.26.24:8080] --
2020/03/10 22:38:27.506 WARNING [jg-async-http-timer-1-1][guru.jini.arch.impl.servicediscovery.ServiceImpl.failedTest] # Failed: java.util.concurrent.TimeoutException: Request timeout to 100.96.26.24:8080 after 1000 ms]
2 seconds later... Call 3 - success
2020/03/10 22:38:28.471 FINE    [jg-es-1][guru.jini.arch.impl.other.HttpImpl.doHttpMethodReactive] # Sending [GET] request to [http://100.96.26.24:8080] --
2020/03/10 22:38:28.475 FINE    [jg-async-http-3-1][guru.jini.arch.impl.rest.JaxRsResponse.<init>] # Response to [GET] on [http://100.96.26.24:8080] with RequestId [4545818464] after [3.483304]ms --

Here is the tcpdump for that period taken from within the running docker container:

Call 1
22:38:24.472285 IP wakanda-wep-v024-428bk.45124 > 100.96.26.24.8080: Flags [S], seq 2419932923, win 65535, options [mss 8911,sackOK,TS val 1192127411 ecr 0,nop,wscale 9], length 0
22:38:24.472837 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45124: Flags [S.], seq 331830089, ack 2419932924, win 65535, options [mss 8911,sackOK,TS val 2177727951 ecr 1192127411,nop,wscale 9], length 0
22:38:24.472853 IP wakanda-wep-v024-428bk.45124 > 100.96.26.24.8080: Flags [.], ack 1, win 128, options [nop,nop,TS val 1192127412 ecr 2177727951], length 0
22:38:24.473302 IP wakanda-wep-v024-428bk.45124 > 100.96.26.24.8080: Flags [P.], seq 1:219, ack 1, win 128, options [nop,nop,TS val 1192127412 ecr 2177727951], length 218: HTTP: GET / HTTP/1.1
22:38:24.473711 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45124: Flags [.], ack 219, win 131, options [nop,nop,TS val 2177727952 ecr 1192127412], length 0
22:38:24.475130 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45124: Flags [P.], seq 1:18, ack 219, win 131, options [nop,nop,TS val 2177727954 ecr 1192127412], length 17: HTTP: HTTP/1.0 200 OK
22:38:24.475140 IP wakanda-wep-v024-428bk.45124 > 100.96.26.24.8080: Flags [.], ack 18, win 128, options [nop,nop,TS val 1192127414 ecr 2177727954], length 0
22:38:24.475278 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45124: Flags [FP.], seq 18:3550, ack 219, win 131, options [nop,nop,TS val 2177727954 ecr 1192127412], length 3532: HTTP
22:38:24.475286 IP wakanda-wep-v024-428bk.45124 > 100.96.26.24.8080: Flags [.], ack 3551, win 163, options [nop,nop,TS val 1192127414 ecr 2177727954], length 0
22:38:24.475335 IP wakanda-wep-v024-428bk.45124 > 100.96.26.24.8080: Flags [F.], seq 219, ack 3551, win 163, options [nop,nop,TS val 1192127414 ecr 2177727954], length 0
22:38:24.475750 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45124: Flags [.], ack 220, win 131, options [nop,nop,TS val 2177727954 ecr 1192127414], length 0

Call 3
22:38:28.472442 IP wakanda-wep-v024-428bk.45182 > 100.96.26.24.8080: Flags [S], seq 1259113428, win 65535, options [mss 8911,sackOK,TS val 1192131411 ecr 0,nop,wscale 9], length 0
22:38:28.472999 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45182: Flags [S.], seq 3440185005, ack 1259113429, win 65535, options [mss 8911,sackOK,TS val 2177731951 ecr 1192131411,nop,wscale 9], length 0
22:38:28.473031 IP wakanda-wep-v024-428bk.45182 > 100.96.26.24.8080: Flags [.], ack 1, win 128, options [nop,nop,TS val 1192131412 ecr 2177731951], length 0
22:38:28.473366 IP wakanda-wep-v024-428bk.45182 > 100.96.26.24.8080: Flags [P.], seq 1:219, ack 1, win 128, options [nop,nop,TS val 1192131412 ecr 2177731951], length 218: HTTP: GET / HTTP/1.1
22:38:28.473773 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45182: Flags [.], ack 219, win 131, options [nop,nop,TS val 2177731952 ecr 1192131412], length 0
22:38:28.475348 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45182: Flags [P.], seq 1:18, ack 219, win 131, options [nop,nop,TS val 2177731954 ecr 1192131412], length 17: HTTP: HTTP/1.0 200 OK
22:38:28.475361 IP wakanda-wep-v024-428bk.45182 > 100.96.26.24.8080: Flags [.], ack 18, win 128, options [nop,nop,TS val 1192131414 ecr 2177731954], length 0
22:38:28.475492 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45182: Flags [FP.], seq 18:3550, ack 219, win 131, options [nop,nop,TS val 2177731954 ecr 1192131412], length 3532: HTTP
22:38:28.475501 IP wakanda-wep-v024-428bk.45182 > 100.96.26.24.8080: Flags [.], ack 3551, win 163, options [nop,nop,TS val 1192131414 ecr 2177731954], length 0
22:38:28.475545 IP wakanda-wep-v024-428bk.45182 > 100.96.26.24.8080: Flags [F.], seq 219, ack 3551, win 163, options [nop,nop,TS val 1192131414 ecr 2177731954], length 0
22:38:28.476074 IP 100.96.26.24.8080 > wakanda-wep-v024-428bk.45182: Flags [.], ack 220, win 131, options [nop,nop,TS val 2177731954 ecr 1192131414], length 0

As you can see the request for call 2 at 22:38:26 is not even seen in the TCP dump. This explains why there is a timeout as the request is not even getting onto the network.

I'm stumped as to where to look. We've tried different JVMs (hotspot and openj9), different HTTP clients within the Java code. All with no change. If we set the timeout really high it makes no difference - the packets are never seen on tcpdump.

The k8s cluster uses cilium and the cluster is running normally. No network issues, memory, cpu spikes at these times. Other pods in the cluster do not have this issue. We have seen this issue on 2 different clusters set up independently and always experienced by pods running this certain java microservice. The microservice running outside of k8s in plain docker works fine with no timeouts whatsoever.

Some more info: Java is jdk 11. Container OS is Ubuntu 18.04. Nodes are in AWS EC2 and running k8s v1.13.9. Node OS is Container Linux by CoreOS 2345.3.0 (Rhyolite) Kernel version 4.19.106-coreos. Docker is docker://18.6.3

service manifest:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: wakanda-wep
  annotations:
    moniker.spinnaker.io/application: wakanda-wep
    moniker.spinnaker.io/cluster: deployment wakanda-wep
    traffic.spinnaker.io/load-balancers: '["service wakanda-wep"]'
  labels:
    app.kubernetes.io/name: wakanda-wep
    app.kubernetes.io/managed-by: spinnaker
spec:
  replicas: 1
  revisionHistoryLimit: 1
  selector:
    matchLabels:
      app.kubernetes.io/name: wakanda-wep
  template:
    metadata:
      annotations:
        moniker.spinnaker.io/application: wakanda-wep
        moniker.spinnaker.io/cluster: deployment wakanda-wep
      labels:
        app.kubernetes.io/name: wakanda-wep
        app.kubernetes.io/managed-by: spinnaker
    spec:
      containers:
      - name: wakanda-wep
        image: xxx/wakanda-wep
        imagePullPolicy: Always
        envFrom:
          - configMapRef:
              name: wakanda-wep
        env:
          - name: XXX
            valueFrom:
              secretKeyRef:
                key: XXX
                name: XXX         
        resources:
          limits:
            cpu: 2000m
            memory: 2000Mi
          requests:
            cpu: 1000m
            memory: 1000Mi
        ports:
          - containerPort: 8000
            name: http
            protocol: TCP
        livenessProbe:
          failureThreshold: 5
          httpGet:
            path: wep-conductor/rest/v1/isup
            port: 8000
          initialDelaySeconds: 60
          periodSeconds: 3
          timeoutSeconds: 1
        readinessProbe:
          failureThreshold: 5
          httpGet:
            path: wep-conductor/rest/v1/isup
            port: 8000
          initialDelaySeconds: 30
          periodSeconds: 5
          timeoutSeconds: 1

ingress:
  enabled: true
  annotations:
    nginx.ingress.kubernetes.io/rewrite-target: /$2
  labels:
    app: wakanda-wep
  path: /prod/wep(/|$)(.*)
  servicePort: https
  hosts:
    - internal-api.xxx.yyy
  tls:
    - hosts:
        - internal-api.xxx.yyy
      secretName: xxx

service:
  enabled: true
  ports:
    https:
      port: 443
      targetPort: 8000
      protocol: TCP

horizontalPodAutoscaler:
  enabled: true
  minReplicas: 1
  maxReplicas: 3
  avgCpuUtilization: 80
  avgMemoryUtilization: 80

canary:
  enabled: false

Basic diagram illustrating the situation: Diagram

Where should we even start to look and any clues on what could cause this?