Intermittent broken pipe

[nabbott2008]

Bug description
We are seeing
[Envoy (Epoch 0)] [2020-05-27 20:35:08.309][32][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:452] [C1340] idle timeout
in istio-proxy logs for TCP connections.
[ ] Configuration Infrastructure
[ ] Docs
[ ] Installation
[X] Networking
[ ] Performance and Scalability
[ ] Policies and Telemetry
[ ] Security
[ ] Test and Release
[ ] User Experience
[ ] Developer Infrastructure
Expected behavior
As this is a TCP connection, we shouldn't be seeing these 60m timeouts from what I can see in the documentation - it looks as though the connection is being treat as a HTTP connection.
We upgraded recently from Istio 1.3.6 and we weren't seeing these issues.
Steps to reproduce the bug
Here is the service we're testing against:

kind: Service
metadata:
  annotations:
    service.alpha.kubernetes.io/tolerate-unready-endpoints: "true"
  creationTimestamp: "2020-05-26T07:08:07Z"
  labels:
    app: abc-opensource
    chart: abc-opensource-0.29.0
    heritage: Tiller
    product: redis
    release: abc-redis
  name: abc-redis-opensource-announce-0
  namespace: abc
  resourceVersion: "29305795"
  selfLink: /api/v1/namespaces/abc/services/abc-redis-opensource-announce-0
  uid: e3629883-79fe-4304-8cb1-9b544ed152ad
spec:
  clusterIP:  1.2.3.4
  ports:
  - name: tcp-server
    port: 6379
    protocol: TCP
    targetPort: redis
  - name: tcp-sentinel
    port: 26379
    protocol: TCP
    targetPort: sentinel
  publishNotReadyAddresses: true
  selector:
    app: abc-opensource
    release: abc-redis
    statefulset.kubernetes.io/pod-name: abc-redis-opensource-server-0
  sessionAffinity: None
  type: ClusterIP
status:
  loadBalancer: {}

Version (include the output of istioctl version --remote and kubectl version and helm version if you used Helm)

client version: 1.5.4
egressgateway version: 1.5.4
ingressgateway version: 1.5.4
ingressgateway version: 1.5.4
ingressgateway-public version:
pilot version: 1.5.4
data plane version: 1.5.1 (32 proxies), 1.5.4 (173 proxies)

Client Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.9", GitCommit:"a17149e1a189050796ced469dbd78d380f2ed5ef", GitTreeState:"clean", BuildDate:"2020-04-16T11:44:51Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"16+", GitVersion:"v1.16.8-eks-e16311", GitCommit:"e163110a04dcb2f39c3325af96d019b4925419eb", GitTreeState:"clean", BuildDate:"2020-03-27T22:37:12Z", GoVersion:"go1.13.8", Compiler:"gc", Platform:"linux/amd64"}

Client: &version.Version{SemVer:"v2.16.7", GitCommit:"5f2584fd3d35552c4af26036f0c464191287986b", GitTreeState:"clean"}
Server: &version.Version{SemVer:"v2.16.6", GitCommit:"dd2e5695da88625b190e6b22e9542550ab503a47", GitTreeState:"clean"}

The client uses jredis. We see the issue where the client is disconnected from sentinel:
Lost connection to Sentinel at abc-redis-opensource-announce-0:26379. Sleeping 5000ms and retrying.
The issue that is causing us most pain though, is when we ask redis client to make a new request. It seems jredis creates a connection to redis when it starts and then this connection is timed out by istio. This means when any of our apps make a new request to jredis, it doesn't have a connection to redis established and needs to create a new one. We see

redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketException: Broken pipe (Write failed)","rootCause":"Broken pipe (Write failed)"}]}}

We are seeing similar issues between other apps but finding that harder to replicate.
We weren't seeing these issues on 1.3.6 and we're still not seeing these issues on other clusters running that version
How was Istio installed?
Using operator.
Environment where bug was observed (cloud vendor, OS, etc)
EKS

[christian-posta]

Could you paste the json output for the listener in question? you can use istioctl proxy-config listeners to get that

[nabbott2008]

    {
        "name": "10.100.230.235_26379",
        "address": {
            "socketAddress": {
                "address": "10.100.230.235",
                "portValue": 26379
            }
        },
        "filterChains": [
            {
                "filters": [
                    {
                        "name": "istio.stats",
                        "typedConfig": {
                            "@type": "type.googleapis.com/udpa.type.v1.TypedStruct",
                            "typeUrl": "type.googleapis.com/envoy.extensions.filters.network.wasm.v3.Wasm",
                            "value": {
                                "config": {
                                    "configuration": "{\n  \"debug\": \"false\",\n  \"stat_prefix\": \"istio\"\n}\n",
                                    "root_id": "stats_outbound",
                                    "vm_config": {
                                        "code": {
                                            "local": {
                                                "inline_string": "envoy.wasm.stats"
                                            }
                                        },
                                        "runtime": "envoy.wasm.runtime.null",
                                        "vm_id": "tcp_stats_outbound"
                                    }
                                }
                            }
                        }
                    },
                    {
                        "name": "envoy.tcp_proxy",
                        "typedConfig": {
                            "@type": "type.googleapis.com/envoy.config.filter.network.tcp_proxy.v2.TcpProxy",
                            "statPrefix": "outbound|26379||dds-redis-opensource-announce-0.abc.svc.cluster.local",
                            "cluster": "outbound|26379||dds-redis-opensource-announce-0.abc.svc.cluster.local",
                            "accessLog": [
                                {
                                    "name": "envoy.file_access_log",
                                    "typedConfig": {
                                        "@type": "type.googleapis.com/envoy.config.accesslog.v2.FileAccessLog",
                                        "path": "/dev/stdout",
                                        "format": "[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% \"%DYNAMIC_METADATA(istio.mixer:status)%\" \"%UPSTREAM_TRANSPORT_FAILURE_REASON%\" %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\" \"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\" %UPSTREAM_CLUSTER% %UPSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_REMOTE_ADDRESS% %REQUESTED_SERVER_NAME% %ROUTE_NAME%\n"
[
    {
        "name": "10.100.230.235_26379",
        "address": {
            "socketAddress": {
                "address": "10.100.230.235",
                "portValue": 26379
            }
        },
        "filterChains": [
            {
                "filters": [
                    {
                        "name": "istio.stats",
                        "typedConfig": {
                            "@type": "type.googleapis.com/udpa.type.v1.TypedStruct",
                            "typeUrl": "type.googleapis.com/envoy.extensions.filters.network.wasm.v3.Wasm",
                            "value": {
                                "config": {
                                    "configuration": "{\n  \"debug\": \"false\",\n  \"stat_prefix\": \"istio\"\n}\n",
                                    "root_id": "stats_outbound",
                                    "vm_config": {
                                        "code": {
                                            "local": {
                                                "inline_string": "envoy.wasm.stats"
                                            }
                                        },
                                        "runtime": "envoy.wasm.runtime.null",
                                        "vm_id": "tcp_stats_outbound"
                                    }
                                }
                            }
                        }
                    },
                    {
                        "name": "envoy.tcp_proxy",
                        "typedConfig": {
                            "@type": "type.googleapis.com/envoy.config.filter.network.tcp_proxy.v2.TcpProxy",
                            "statPrefix": "outbound|26379||dds-redis-opensource-announce-0.abc.svc.cluster.local",
                            "cluster": "outbound|26379||dds-redis-opensource-announce-0.abc.svc.cluster.local",
                            "accessLog": [
                                {
                                    "name": "envoy.file_access_log",
                                    "typedConfig": {
                                        "@type": "type.googleapis.com/envoy.config.accesslog.v2.FileAccessLog",
                                        "path": "/dev/stdout",
                                        "format": "[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% \"%DYNAMIC_METADATA(istio.mixer:status)%\" \"%UPSTREAM_TRANSPORT_FAILURE_REASON%\" %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\" \"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\" %UPSTREAM_CLUSTER% %UPSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_REMOTE_ADDRESS% %REQUESTED_SERVER_NAME% %ROUTE_NAME%\n"
                                    }
                                }
                            ]
                        }
                    }
                ]
            }
        ],
        "deprecatedV1": {
            "bindToPort": false
        },
        "trafficDirection": "OUTBOUND"
    }
]

apologies, I made a mistake in logging the issue. What we're actually seeing is this tcp timout

2020-06-23 14:32:55.339	[Envoy (Epoch 0)] [2020-06-23 14:32:55.280][35][debug][conn_handler] [external/envoy/source/server/connection_handler_impl.cc:353] [C403] new connection
2020-06-23 14:32:55.339	[Envoy (Epoch 0)] [2020-06-23 14:32:55.280][35][debug][filter] [external/envoy/source/common/tcp_proxy/tcp_proxy.cc:381] [C403] Creating connection to cluster outbound|26379||dds-redis-opensource-announce-0.abc.svc.cluster.local
2020-06-23 14:32:55.339	[Envoy (Epoch 0)] [2020-06-23 14:32:55.280][35][debug][filter] [external/envoy/source/common/tcp_proxy/tcp_proxy.cc:232] [C403] new tcp proxy session
2020-06-23 15:32:56.133	[Envoy (Epoch 0)] [2020-06-23 15:32:55.284][35][debug][conn_handler] [external/envoy/source/server/connection_handler_impl.cc:86] [C403] adding to cleanup list
2020-06-23 15:32:56.133	[Envoy (Epoch 0)] [2020-06-23 15:32:55.284][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:192] [C403] closing socket: 1
2020-06-23 15:32:56.133	[Envoy (Epoch 0)] [2020-06-23 15:32:55.284][35][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C403] closing data_to_write=0 type=1
2020-06-23 15:32:56.133	[Envoy (Epoch 0)] [2020-06-23 15:32:55.284][35][debug][filter] [external/envoy/source/common/tcp_proxy/tcp_proxy.cc:597] [C403] Session timed out

and we can't find out how to change this hourly timeout - can't see in documentation how to do this

[christian-posta]

You can try setting ISTIO_META_IDLE_TIMEOUT env variable to a duration (ie, 24h0m0s) on the Istio-proxy for this workload and that should do the trick. Let me know how that works for you.

[nabbott2008]

Hi,

Thanks for the response. I added the following annotation:

        proxy.istio.io/config: |-
          proxyMetadata:
            ISTIO_META_IDLE_TIMEOUT: 24h0m0s

I tried adding this to the client and server in this scenario and it didn't stop the timeouts.

We have also tried to add this envoyfilter

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  creationTimestamp: "2020-06-29T09:24:30Z"
  generation: 1
  name: redis-test2
  namespace: abc
  resourceVersion: "54665918"
  selfLink: /apis/networking.istio.io/v1alpha3/namespaces/rsb/envoyfilters/redis-test2
  uid: e7e60a2d-92b1-4b07-93ac-f5677ecbd751
spec:
  configPatches:
  - applyTo: NETWORK_FILTER
    match:
      context: SIDECAR_OUTBOUND
      listener:
        filterChain:
          filter:
            name: envoy.tcp_proxy
        portNumber: 6379
    patch:
      operation: MERGE
      value:
        name: envoy.tcp_proxy
        typed_config:
          '@type': type.googleapis.com/envoy.config.filter.network.tcp_proxy.v2.TcpProxy
          idle_timeout: 24h
  workloadSelector:
    labels:
      app: app

Can see this added to config:

kubectl -n rsb get envoyfilter redis-test -o yaml
---
---
---
                        "name": "envoy.tcp_proxy",
                        "typedConfig": {
                            "@type": "type.googleapis.com/envoy.config.filter.network.tcp_proxy.v2.TcpProxy",
                            "statPrefix": "outbound|6379||abc-redis-opensource.abc.svc.cluster.local",
                            "cluster": "outbound|6379||abc-redis-opensource.abc.svc.cluster.local",
                            "idleTimeout": "86400s"
                        }
---
---
---

However, still seeing the hourly timeouts. (if I do set above to 60 seconds, I do get 60 second timeouts so think this is a timeout on the front end rather than the one we're having issues with)
I think I need to try and set the timeout on the cluster config but I'm having difficulties doing that at the moment.

[christian-posta]

Yah I'm not sure why the annotation doesn't work (I'll check) but just add it as an env variable like I previously mentioned... add it to the client side proxy:

ISTIO_META_IDLE_TIMEOUT
24h0m0s

[nabbott2008]

kubectl -n abc exec -it app-f6f79bcf6-ldjgb -c istio-proxy -- env | grep ISTIO_META_IDLE_TIMEOUT
ISTIO_META_IDLE_TIMEOUT=24h0m0s

It adds correctly using the annotation but, unfortunately, don't see any change to the timeout.

[christian-posta]

Ah okay let me check the cluster config part. There may not be a way to do that at the moment. Will report back.

[nabbott2008]

Thanks. N.B. We are using Istio 1.6.2 now.

[christian-posta]

I gotta be honest, I'm not able to reproduce this. I'm getting the idle_timeout enforced by the tcp_proxy correctly. Now.. if you do have filters on the cluster as well, we should take a look at those... can you give me the json output of this cluster outbound|26379||dds-redis-opensource-announce-0.abc.svc.cluster.local for the proxy on the client side of the connection?

Worst case, I can jump on a zoom call with you and we can take a look together.

[courcelm]

I'm having a similar issue on Istio 1.5.8. TCP connections are dropped for various service types (SSL, postgres, redis) after 1 hour. Like @nabbott2008 , settings ISTIO_META_IDLE_TIMEOUT to 24h0m0s did not work but 30s did work.

[jmp0xf]

+1, We are seeing exactly the same issue as @courcelm described, on Istio 1.5.6.