Almost every app gets UC errors, 0.012% of all requests in 24h period

I've noticed pretty much every application periodically gets this, a 503 with the envoy code UC.

It's retried as you can see, but it's bothering me that I cannot get to the bottom of why it is happening.  My destinationrule should deal with any connection timeouts etc:
apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  name: sauron-graphql-server
spec:
  host: app
  trafficPolicy:
    connectionPool:
      http:
        http1MaxPendingRequests: 1024
        http2MaxRequests: 10240
        idleTimeout: 5m
        maxRequestsPerConnection: 1024
      tcp:
        maxConnections: 10240
        tcpKeepalive:
          interval: 1m
          time: 3m
    loadBalancer:
      simple: LEAST_CONN
    outlierDetection:
      baseEjectionTime: 5s
      consecutiveErrors: 5
      interval: 5s
      maxEjectionPercent: 50
      minHealthPercent: 50
    tls:
      mode: ISTIO_MUTUAL

The frequency of these bothers me, because across a distributed service graph, we can get spikes in latency on client requests as a result.

Do you know if this is a new issue you are experiencing?

Annoyingly, I'm not sure :-(
Historically I've only really been looking at reporter=source, however investigating some latency blips recently i've started looking at reporter=destination, which is where I saw these.

Well 10 minutes after restarting them, I saw another :'( so guess I didn't need to wait overnight!

Would you be able to post Envoy router and connection pool logs? I'm wondering if it's a case of a closed-by-upstream connection being reused that results in a 503 (recently fixed in Envoy but hasn't been released yet). Also, can you try setting idleTimeout to a much smaller value like 15s to see if the number of 503s changes at all?

The router logs in debug are difficult to capture, the failure rate is quite low, say 0.02% - it becomes difficult to capture logs from all instances for a given app and catch the UC.
I'll try adjusting the idleTimeout though and see what happens.

15s made no difference :shrug:

OK @arianmotamedi @howardjohn  I persevered and managed to catch one with router and connection logs:
[2019-05-06 20:22:57.530][30][debug][router] [external/envoy/source/common/router/router.cc:320] [C17068][S9430344543646919123] cluster 'inbound|80|http-web|app.sauron-seo-app.svc.cluster.local' match for URL '/cars/peugeot/partner/combi'
[2019-05-06 20:22:57.530][30][debug][router] [external/envoy/source/common/router/router.cc:381] [C17068][S9430344543646919123] router decoding headers:
':authority', 'app.sauron-seo-app'
':path', '/cars/peugeot/partner/combi'
':method', 'GET'
... etc etc etc

[2019-05-06 20:22:57.530][30][debug][router] [external/envoy/source/common/router/router.cc:1165] [C17068][S9430344543646919123] pool ready
[2019-05-06 20:22:57.531][28][debug][router] [external/envoy/source/common/router/router.cc:717] [C19043][S5917390943479852622] upstream headers complete: end_stream=false
[2019-05-06 20:22:57.532][28][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C19043] closing data_to_write=1684 type=2
[2019-05-06 20:22:57.532][28][debug][connection] [external/envoy/source/common/network/connection_impl.cc:153] [C19043] setting delayed close timer with timeout 1000 ms
[2019-05-06 20:22:57.536][28][debug][router] [external/envoy/source/common/router/router.cc:320] [C0][S13455846817491226201] cluster 'outbound|15004||istio-telemetry.istio-system.svc.cluster.local' match for URL '/istio.mixer.v1.Mixer/Report'
[2019-05-06 20:22:57.536][28][debug][router] [external/envoy/source/common/router/router.cc:381] [C0][S13455846817491226201] router decoding headers:
':method', 'POST'
':path', '/istio.mixer.v1.Mixer/Report'
...etc etc etc

[2019-05-06 20:22:57.536][28][debug][router] [external/envoy/source/common/router/router.cc:1165] [C0][S13455846817491226201] pool ready
[2019-05-06 20:22:57.540][28][debug][router] [external/envoy/source/common/router/router.cc:717] [C0][S13455846817491226201] upstream headers complete: end_stream=false
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C19020] remote close
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C19020] closing socket: 0
[2019-05-06 20:22:57.559][30][debug][router] [external/envoy/source/common/router/router.cc:644] [C17068][S9430344543646919123] upstream reset: reset reason connection termination
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:461] [C19040] remote early close
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C19040] closing socket: 0
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C17068] remote close
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C17068] closing socket: 0
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:244] [C17068] SSL shutdown: rc=1
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:175] [C17068]
[2019-05-06 20:22:57.581][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C19044] handshake error: 2
[2019-05-06 20:22:57.581][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C19044] handshake error: 2
[2019-05-06 20:22:57.583][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:131] [C19044] handshake complete

I feel there is overlap with https://github.com/istio/istio/issues/13616, even though @jaygorrell is specifically talking about his observations during deployments.

I also want to call out the messages i put on slack the other day, we have multiple app that do connection pooling having their connections terminated for no reason, all with the same error:
searchone-consumer talking to search-one (in cluster -> in cluster)
2019-05-02 17:01:59.924  WARN 1 --- [ice-executor-18] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
sauron-web talking to abtest-allocator (in cluster -> in cluster)
sauron.http.endpoint.HttpEndpointException: java.io.InterruptedIOException: Connection has been shut down
sauron-web talking to ods (in cluster -> on prem)
2019-05-02 13:29:56,204 ERROR u.c.a.o.ODSClientImpl:72 - Logging to ODS failed: Connection has been shut down for message:

Wait, in the logs you posted, C17068 is the one being reset, but I don't see a log saying the connection is being reused. If a reset is happening on new connection, then idle/keep alive timeouts won't have anything to do with the failure. Besides that, these DestinationRule timeouts are applied to requests coming into your service's sidecar; I don't believe sidecar ingress -> local service sees these (you can verify this by checking the cluster configuration for inbound|80|http-web|app.sauron-seo-app.svc.cluster.local).

We do apply the outlier detection rules to inbound, not sure about the rest. I don't think this actually really does anything though, since we have the minHealthPercent

TBH I don't know what the problem is.  I'm just observing the failures with the code UC.
Here are sections from the config dump for that cluster:
{
"version_info": "2019-05-06T20:31:35Z/62",
"cluster": {
"name": "inbound|80|http-web|app.sauron-seo-app.svc.cluster.local",
"type": "STATIC",
"connect_timeout": "10s",
"circuit_breakers": {
"thresholds": [
{}
]
},
"metadata": {
"filter_metadata": {
"istio": {
"config": "/apis/networking.istio.io/v1alpha3/namespaces/istio-system/destination-rule/default"
}
}
},
"load_assignment": {
"cluster_name": "inbound|80|http-web|app.sauron-seo-app.svc.cluster.local",
"endpoints": [
{
"lb_endpoints": [
{
"endpoint": {
"address": {
"socket_address": {
"address": "<IP_ADDRESS>",
"port_value": 8080
}
}
}
}
]
}
]
}
},
"last_updated": "2019-05-06T20:31:54.631Z"
}

"name": "inbound|80|http-web|app.sauron-seo-app.svc.cluster.local",
"validate_clusters": false,
"virtual_hosts": [
{
"name": "inbound|http|80",
"routes": [
{
"decorator": {
"operation": "app.sauron-seo-app.svc.cluster.local:80/*"
},
"route": {
"cluster": "inbound|80|http-web|app.sauron-seo-app.svc.cluster.local",
"timeout": "0s",
"max_grpc_timeout": "0s"
},
"match": {
"prefix": "/"
},
"per_filter_config": {
"mixer": {
"mixer_attributes": {
"attributes": {
"destination.service.namespace": {
"string_value": "sauron-seo-app"
},
"destination.service.name": {
"string_value": "app"
},
"destination.service.host": {
"string_value": "app.sauron-seo-app.svc.cluster.local"
},
"destination.service.uid": {
"string_value": "istio://sauron-seo-app/services/app"
}
}
},
"disable_check_calls": true
}
}
}
],
"domains": [
"*"
]
}
]

{
"route_config": {
"name": "inbound|80|http-web|app.sauron-seo-app.svc.cluster.local",
"virtual_hosts": [
{
"name": "inbound|http|80",
"domains": [
"*"
],
"routes": [
{
"match": {
"prefix": "/"
},
"route": {
"cluster": "inbound|80|http-web|app.sauron-seo-app.svc.cluster.local",
"timeout": "0s",
"max_grpc_timeout": "0s"
},
"decorator": {
"operation": "app.sauron-seo-app.svc.cluster.local:80/*"
},
"per_filter_config": {
"mixer": {
"disable_check_calls": true,
"mixer_attributes": {
"attributes": {
"destination.service.name": {
"string_value": "app"
},
"destination.service.namespace": {
"string_value": "sauron-seo-app"
},
"destination.service.uid": {
"string_value": "istio://sauron-seo-app/services/app"
},
"destination.service.host": {
"string_value": "app.sauron-seo-app.svc.cluster.local"
}
}
}
}
}
}
]
}
],
"validate_clusters": false
},
"last_updated": "2019-05-06T20:31:54.657Z"
}

I mean, these logs don't sound particular healthy?
[2019-05-06 20:22:57.559][30][debug][router] [external/envoy/source/common/router/router.cc:644] [C17068][S9430344543646919123] upstream reset: reset reason connection termination
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C17068] remote close
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C17068] closing socket: 0
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:244] [C17068] SSL shutdown: rc=1
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:175] [C17068]

I mean, these logs don't sound particular healthy?

They don't, it's definitely an issue, but it's not the same issue as others reported that was caused due to an existing connection being closed by upstream without downstream Envoy acknowledging it and returning it to the connection pool, which is what idleTimeout was added for. In those cases, you'd see an explicit log saying the connection is being reused:

[debug][pool] external/envoy/source/common/http/http1/conn_pool.cc:89] [C502] using existing connection

If this isn't in your logs for C17068 then it's not something that idle_timeout/tcp keep_alive settings can fix since those settings don't have any effect on new connections (and as you can see they're not applied to ingress cluster config anyway). According to these logs, this 503 happened from destination Envoy to your service (not source Envoy -> destination Envoy). Are there any logs at all from your sauron-seo-app service around the same time?

Ah right so it's separate to the other issues then.
@arianmotamedi those logs above are from sauron-seo-app.  In the example above it is consumer-gateway -> sauron-seo-app.

@Stono these are sauron-seo-app's sidecar logs, I meant sauron-seo-app's logs to see if there's any indication that your app forcibly closed a connection, since "upstream" in sauron-seo-app's sidecar refers to the app itself.
The other thing you should check is cluster statistics for inbound|80|http-web|app.sauron-seo-app.svc.cluster.local (hit the /stats endpoint and search for cluster.inbound|80|http-web|app.sauron-seo-app.svc.cluster.local.upstream_) to see if anything other than cx_destroy_remote and cx_destroy_remote_with_active_rq stands out.

There is nothing in the application logs about it killing connections, no.
Does envoy -> the app connection pool?
If so, is that pool sending keep alives to the app?
Here are all the cx stats for one of the instances that's just been spawned (2 mins ago) and has had a UC already (just one):
cluster.xds-grpc.upstream_cx_close_notify: 0
cluster.xds-grpc.upstream_cx_connect_attempts_exceeded: 0
cluster.xds-grpc.upstream_cx_connect_fail: 0
cluster.xds-grpc.upstream_cx_connect_timeout: 0
cluster.xds-grpc.upstream_cx_destroy: 0
cluster.xds-grpc.upstream_cx_destroy_local: 0
cluster.xds-grpc.upstream_cx_destroy_local_with_active_rq: 0
cluster.xds-grpc.upstream_cx_destroy_remote: 0
cluster.xds-grpc.upstream_cx_destroy_remote_with_active_rq: 0
cluster.xds-grpc.upstream_cx_destroy_with_active_rq: 0
cluster.xds-grpc.upstream_cx_http1_total: 0
cluster.xds-grpc.upstream_cx_http2_total: 1
cluster.xds-grpc.upstream_cx_idle_timeout: 0
cluster.xds-grpc.upstream_cx_max_requests: 0
cluster.xds-grpc.upstream_cx_none_healthy: 1
cluster.xds-grpc.upstream_cx_overflow: 0
cluster.xds-grpc.upstream_cx_protocol_error: 0
cluster.xds-grpc.upstream_cx_rx_bytes_buffered: 134
cluster.xds-grpc.upstream_cx_rx_bytes_total: 69136
cluster.xds-grpc.upstream_cx_total: 1
cluster.xds-grpc.upstream_cx_tx_bytes_buffered: 0
cluster.xds-grpc.upstream_cx_tx_bytes_total: 34061
cluster.xds-grpc.upstream_cx_connect_ms: P0(nan,8) P25(nan,8.025) P50(nan,8.05) P75(nan,8.075) P90(nan,8.09) P95(nan,8.095) P99(nan,8.099) P99.5(nan,8.0995) P99.9(nan,8.0999) P100(nan,8.1)
cluster.xds-grpc.upstream_cx_length_ms: No recorded values

And here are the rest of the stats (you can see the 503):
cluster.xds-grpc.internal.upstream_rq_200: 1
cluster.xds-grpc.internal.upstream_rq_2xx: 1
cluster.xds-grpc.internal.upstream_rq_503: 1
cluster.xds-grpc.internal.upstream_rq_5xx: 1
cluster.xds-grpc.internal.upstream_rq_completed: 2
cluster.xds-grpc.lb_healthy_panic: 1
cluster.xds-grpc.max_host_weight: 1
cluster.xds-grpc.membership_change: 1
cluster.xds-grpc.membership_healthy: 1
cluster.xds-grpc.membership_total: 1
cluster.xds-grpc.ssl.ciphers.ECDHE-RSA-AES128-GCM-SHA256: 1
cluster.xds-grpc.ssl.curves.X25519: 1
cluster.xds-grpc.ssl.handshake: 1
cluster.xds-grpc.ssl.sigalgs.rsa_pss_rsae_sha256: 1
cluster.xds-grpc.ssl.versions.TLSv1.2: 1
cluster.xds-grpc.update_attempt: 96
cluster.xds-grpc.update_no_rebuild: 95
cluster.xds-grpc.update_success: 96
cluster.xds-grpc.upstream_cx_active: 1
cluster.xds-grpc.upstream_cx_http2_total: 1
cluster.xds-grpc.upstream_cx_none_healthy: 1
cluster.xds-grpc.upstream_cx_rx_bytes_buffered: 134
cluster.xds-grpc.upstream_cx_rx_bytes_total: 69270
cluster.xds-grpc.upstream_cx_total: 1
cluster.xds-grpc.upstream_cx_tx_bytes_total: 36311
cluster.xds-grpc.upstream_rq_200: 1
cluster.xds-grpc.upstream_rq_2xx: 1
cluster.xds-grpc.upstream_rq_503: 1
cluster.xds-grpc.upstream_rq_5xx: 1
cluster.xds-grpc.upstream_rq_active: 1
cluster.xds-grpc.upstream_rq_completed: 2
cluster.xds-grpc.upstream_rq_pending_total: 1
cluster.xds-grpc.upstream_rq_total: 1
cluster_manager.active_clusters: 25
cluster_manager.cds.update_attempt: 2
cluster_manager.cds.update_success: 1
cluster_manager.cds.version:<PHONE_NUMBER>6443169755
cluster_manager.cluster_added: 25
cluster_manager.cluster_updated: 5
http_mixer_filter.total_remote_report_calls: 808
http_mixer_filter.total_remote_report_successes: 808
http_mixer_filter.total_report_calls: 4272
listener_manager.lds.update_attempt: 2
listener_manager.lds.update_success: 1
listener_manager.lds.version:<PHONE_NUMBER>6443169755
listener_manager.listener_added: 17
listener_manager.listener_create_success: 34
listener_manager.total_listeners_active: 17
server.concurrency: 2
server.days_until_first_cert_expiring: 25
server.live: 1
server.memory_allocated: 9784536
server.memory_heap_size: 19922944
server.total_connections: 20
server.uptime: 475
server.version: 7600795

OK this issue can be exacerbated when you have more pods:
Take this:
❯ k get pods
NAME                               READY   STATUS    RESTARTS   AGE
redis-commander-7bbbf67df7-mwsms   1/1     Running   0          6d12h
sauron-seo-app-55b7bd4c45-8vkmp    2/2     Running   0          39m
sauron-seo-app-55b7bd4c45-r5dk5    2/2     Running   0          39m
sauron-seo-app-55b7bd4c45-sbj9m    2/2     Running   0          39m

And then look at the first two requests fail:

This app is getting a very small amount of traffic but enough to prevent time outs:

assigning to @duderino for triage, etc.

by-upstream connection being reused that results in a 503 (recently fixed in Envoy but hasn't been released yet).

Can you point me to this PR?   We could potentially cherrypick

@arianmotamedi that is a problem but i don't believe it is the cause of this issue

@Stono we certainly have not proven it's the cause, but I'd like to keep considering it.
@PiotrSikora @silentdai @jplevyak your thoughts please

@duderino https://github.com/envoyproxy/envoy/pull/6578

@duderino if you can get a nightly build with that envoy fix I'm more than happy to test if it has any affect.

I doubt https://github.com/envoyproxy/envoy/pull/6578 is the issue. That only happens to existing connections being reused - according to the logs @Stono posted for one of the 503s, it happened on a new connection. I agree that this seems to be a different issue.

Who is owning the investigation on the istio side?
I'm wondering what else I can do to help debug this.  I need to find a solution

I'm still relatively convinced that these UC's are causing us other problems.  I would appreciate it if someone could look at these connection logs and see if anything stands out.
For context, we have:
[ searchone-consumer (single instance) ] -- POST --> [ search-one (3 instances) ]
searchone-consumer is doing approximately 250 ops/sec, search-one is handling approximately 600 ops/sec.
What we're seeing in searchone-consumer only when we run with istio is this:
2019-05-10 06:31:53.228  WARN 1 --- [ice-executor-24] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
2019-05-10 06:31:53.229  WARN 1 --- [vice-executor-0] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
2019-05-10 06:32:38.109  WARN 1 --- [ice-executor-17] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:33:27.295  WARN 1 --- [ice-executor-12] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:34:25.602  WARN 1 --- [ice-executor-15] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
2019-05-10 06:34:44.835  WARN 1 --- [vice-executor-7] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:35:36.030  WARN 1 --- [ice-executor-15] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:35:51.086  WARN 1 --- [ice-executor-29] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
2019-05-10 06:35:53.626  WARN 1 --- [ice-executor-12] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:36:43.288  WARN 1 --- [ice-executor-19] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:36:56.828  WARN 1 --- [ice-executor-21] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:38:37.290  WARN 1 --- [ice-executor-23] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:39:47.327  WARN 1 --- [vice-executor-6] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:40:42.592  WARN 1 --- [ice-executor-18] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
2019-05-10 06:43:46.387  WARN 1 --- [vice-executor-1] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: Connection has been shut down - retrying
2019-05-10 06:44:03.092  WARN 1 --- [ice-executor-28] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:45:56.775  WARN 1 --- [ice-executor-18] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying
2019-05-10 06:48:10.985  WARN 1 --- [ice-executor-18] u.c.a.s.c.k.service.SearchOneService     : Error talking to S1: null - retrying

Now if istio is connection pooling, and searchone-consumer is connection pooling, I would expect to be seeing so many connection and disconnection attempts in the istio-proxy connection logs.
[2019-05-10 06:53:23.692][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:131] [C1462] handshake complete
[2019-05-10 06:53:23.842][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C1085] closing data_to_write=0 type=1
[2019-05-10 06:53:23.842][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C1085] closing socket: 1
[2019-05-10 06:53:23.842][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:244] [C1085] SSL shutdown: rc=0
[2019-05-10 06:53:23.842][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:175] [C1085]

Please see the attached logs.
search-one-consumer.log
search-one.log

I'm going to try to clean this up a bit to see if I can find the real issue....
I don't see any errors in the search-one-consumer.log or search-one.log.  I see these things that look like errors but they aren't:
[2019-05-10 06:52:55.073][29][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C1441] connecting to <IP_ADDRESS>:8375
[2019-05-10 06:52:55.074][29][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C1441] connection in progress
[2019-05-10 06:52:55.074][29][debug][connection] [external/envoy/source/common/network/connection_impl.cc:517] [C1441] connected
[2019-05-10 06:52:55.074][29][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C1441] handshake error: 2
[2019-05-10 06:52:55.078][29][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C1441] handshake error: 2
[2019-05-10 06:52:55.078][29][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C1441] handshake error: 2
[2019-05-10 06:52:55.079][29][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:131] [C1441] handshake complete

The 2 in "handshake error: 2" comes from #define SSL_ERROR_WANT_READ 2, so that just means there wasn't enough data in the socket recv buffer to complete the handshake for a while, but then the data does arrive and the handshake completes.

The router logs in debug are difficult to capture as they're very verbose, the failure rate is quite low, say 0.02% - it becomes difficult to capture logs from all instances for a given app and catch the UC as i don't shift istio-proxy logs off to external logging (ELK).
I'll try and think of something tomorrow.
In the interim, I'll try adjusting the idleTimeout though and see what happens, but i'm unsure how it would help considering i've configured keep alive to be less than the timeout.

Is this a TCP keepalive (which I think idleTimeout would completely ignore because that looks only for application data (actual payload - bytes on the wire)) or a application level keepalive (e.g., gRPC has this)

Hey,
I tried various configurations of the destinationrules idleTimeout and TCP keep alive.
Didn't make any observable difference!
And tbh we see this on services getting constant traffic so I imagine its actually unlikely to be a keep alive thing.

OK @arianmotamedi @howardjohn I persevered and managed to catch one with router and connection logs.
This is from the destination envoy.
[2019-05-06 20:22:57.530][30][debug][router] [external/envoy/source/common/router/router.cc:320] [C17068][S9430344543646919123] cluster 'inbound|80|http-web|app.sauron-seo-app.svc.cluster.local' match for URL '/cars/peugeot/partner/combi'
[2019-05-06 20:22:57.530][30][debug][router] [external/envoy/source/common/router/router.cc:381] [C17068][S9430344543646919123] router decoding headers:
':authority', 'app.sauron-seo-app'
':path', '/cars/peugeot/partner/combi'
':method', 'GET'
... etc etc etc

[2019-05-06 20:22:57.530][30][debug][router] [external/envoy/source/common/router/router.cc:1165] [C17068][S9430344543646919123] pool ready
[2019-05-06 20:22:57.531][28][debug][router] [external/envoy/source/common/router/router.cc:717] [C19043][S5917390943479852622] upstream headers complete: end_stream=false
[2019-05-06 20:22:57.532][28][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C19043] closing data_to_write=1684 type=2
[2019-05-06 20:22:57.532][28][debug][connection] [external/envoy/source/common/network/connection_impl.cc:153] [C19043] setting delayed close timer with timeout 1000 ms
[2019-05-06 20:22:57.536][28][debug][router] [external/envoy/source/common/router/router.cc:320] [C0][S13455846817491226201] cluster 'outbound|15004||istio-telemetry.istio-system.svc.cluster.local' match for URL '/istio.mixer.v1.Mixer/Report'
[2019-05-06 20:22:57.536][28][debug][router] [external/envoy/source/common/router/router.cc:381] [C0][S13455846817491226201] router decoding headers:
':method', 'POST'
':path', '/istio.mixer.v1.Mixer/Report'
...etc etc etc

[2019-05-06 20:22:57.536][28][debug][router] [external/envoy/source/common/router/router.cc:1165] [C0][S13455846817491226201] pool ready
[2019-05-06 20:22:57.540][28][debug][router] [external/envoy/source/common/router/router.cc:717] [C0][S13455846817491226201] upstream headers complete: end_stream=false
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C19020] remote close
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C19020] closing socket: 0
[2019-05-06 20:22:57.559][30][debug][router] [external/envoy/source/common/router/router.cc:644] [C17068][S9430344543646919123] upstream reset: reset reason connection termination
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:461] [C19040] remote early close
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C19040] closing socket: 0
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C17068] remote close
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C17068] closing socket: 0
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:244] [C17068] SSL shutdown: rc=1
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:175] [C17068]
[2019-05-06 20:22:57.581][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C19044] handshake error: 2
[2019-05-06 20:22:57.581][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:142] [C19044] handshake error: 2
[2019-05-06 20:22:57.583][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:131] [C19044] handshake complete

I think you mean this:
[external/envoy/source/common/network/connection_impl.cc:461] [C19040] remote early close
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C19040] closing socket: 0

That corresponds to this code in Envoy:
  if (events & Event::FileReadyType::Closed) {
    // We never ask for both early close and read at the same time. If we are reading, we want to
    // consume all available data.
    ASSERT(!(events & Event::FileReadyType::Read));
    ENVOY_CONN_LOG(debug, "remote early close", *this);
    closeSocket(ConnectionEvent::RemoteClose);
    return;
  }

@PiotrSikora does this just mean that Envoy was trying to, say, read the next request on a connection but the peer decided to close it's end of the connection?

Yes those are all the logs for a request which 503'd

I mean, these logs don't sound particular healthy?
[2019-05-06 20:22:57.559][30][debug][router] [external/envoy/source/common/router/router.cc:644] [C17068][S9430344543646919123] upstream reset: reset reason connection termination
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C17068] remote close
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C17068] closing socket: 0
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:244] [C17068] SSL shutdown: rc=1
[2019-05-06 20:22:57.560][30][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:175] [C17068]

I think this one means that the source/client sidecar noticed the destination/server sidecar close its end of a TLS connection.    That's only an issue if it closes the connection in the middle of an active transaction (e.g,. HTTP request sent, waiting for a HTTP response).   I don't see it actually interrupting an active transaction here.

Yes those are all the logs for a request which 503'd, I didn't know which bits gave any information as to why ?

How did you associate the connections in those logs with requests that 503?

We can group the search-one-consumer envoy logs into 2 groups.

search-one-consumer-envoy -- search-one envoy.
I see no error in the log.
search-one-consumer -- search-one-consumer envoy
It's always envoy see the remote(search-one-consumer) close first. It seems either consumer or envoy lies. Or something in the middle close the connection.

[2019-05-10 06:48:47.439][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C1173] remote close
[2019-05-10 06:48:47.439][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C1173] closing socket: 0

How did you associate the connections in those logs with requests that 503?

The ... Part showed the response code of 503, how do you think? 😂😂 I just didn't bloat the post with all the headers

How did you associate the connections in those logs with requests that 503?

The ... part i omitted showed the response code of 503, how do you think?  I just didn't bloat the post with all the headers.

Can you show me combined logs that have both the 503 response status and all the events for a connection (e.g,. C19040, or whatever).  I'm trying to piece this together across multiple comments and they all seem to be from different events.

I'm really not sure what else you want.  It's exactly the logs you quoted me on a minute ago with the standard response headers in there, one of which was 503 with a response code UC.  Which could then be viewed in Jager too.
I'll get another one for you tomorrow as it's midnight here.
You're right there a lot of comments on here, that's because I'm trying to give you info from multiple different events, as it happens so much.    When I'm actively trying to investigate the issue and don't hear anything from istio folks for days, all I can do is just continue to gather more information as I presume you're not making any progress.
As I've suggested countless times now, perhaps a more effective way to get to the bottom of the problem would be to just screenshare with me and that way you can explore my cluster as they're happening.
Further to that, the linked post "Sporadic 503 errors" shows that they are easily reproduible from a simple fortio load test.  So maybe just try that yourself rather than relying on cross time zone async Q&A and share your findings?

I don't see any logs anywhere that show me a 503 response with surrounding socket events.   Sorry, I've tried very hard, I just can't find them.
The reason why I'm pushing on this is because I still think envoyproxy/envoy#6578 could address this and I haven't seen anything else that looks like an error.
So I think I should just backport that and you should give it a shot.

Sounds like a plan

Something I found pretty odd today was this trace.  Notice how the first one which UC with a 503 took 150ms to do so?
I don't know what that tells me, if anything - just seems like a rather long time.

OK here's my next finding, we built a small set of services that call each other in a testing environment.
At first we were hitting it with quite a bit of ops/sec, 100+, but didn't see the UC's.  We knocked it down to 2ops/second and quite quickly saw one:

Another interesting observation, we definitely see increased UC's during periods of higher load (in terms of ops/sec) and churn on the cluster (deployments):

This correlates with an increase in EDS pushes:

@howardjohn asked me to try something in preprod, scaling istio-pilot to 0 instances.
I wanted to document the findings here.  As you can see, the pushes stopped as you would expect:

However, we noticed a gradual increase in UC's:

I wouldn't be expecting any UC's here, pilot is offline, sure, but the config is up to date.
Looking in the debug connection logs all i see are connections attempts to pilot:
[2019-05-13 18:25:18.591][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C2187] remote close
[2019-05-13 18:25:18.591][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2187] closing socket: 0
[2019-05-13 18:25:32.048][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C2188] connecting to <IP_ADDRESS>:15011
[2019-05-13 18:25:32.048][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C2188] connection in progress
[2019-05-13 18:25:42.049][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C2188] closing data_to_write=0 type=1
[2019-05-13 18:25:42.049][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2188] closing socket: 1
[2019-05-13 18:26:06.370][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C2189] connecting to <IP_ADDRESS>:15011
[2019-05-13 18:26:06.370][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C2189] connection in progress
[2019-05-13 18:26:16.371][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C2189] closing data_to_write=0 type=1
[2019-05-13 18:26:16.371][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2189] closing socket: 1
[2019-05-13 18:26:22.575][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C2190] connecting to <IP_ADDRESS>:15011
[2019-05-13 18:26:22.576][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C2190] connection in progress
[2019-05-13 18:26:32.577][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C2190] closing data_to_write=0 type=1
[2019-05-13 18:26:32.577][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2190] closing socket: 1
[2019-05-13 18:26:55.119][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C2191] connecting to <IP_ADDRESS>:15011
[2019-05-13 18:26:55.119][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C2191] connection in progress
[2019-05-13 18:27:05.119][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C2191] closing data_to_write=0 type=1
[2019-05-13 18:27:05.119][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2191] closing socket: 1
[2019-05-13 18:27:09.441][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C2192] connecting to <IP_ADDRESS>:15011
[2019-05-13 18:27:09.441][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C2192] connection in progress
[2019-05-13 18:27:19.442][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C2192] closing data_to_write=0 type=1
[2019-05-13 18:27:19.442][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2192] closing socket: 1
[2019-05-13 18:27:46.825][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:644] [C2193] connecting to <IP_ADDRESS>:15011
[2019-05-13 18:27:46.826][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:653] [C2193] connection in progress
[2019-05-13 18:27:56.827][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:101] [C2193] closing data_to_write=0 type=1
[2019-05-13 18:27:56.827][20][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2193] closing socket: 1
[2019-05-13 18:27:57.197][26][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C2176] remote close
[2019-05-13 18:27:57.197][26][debug][connection] [external/envoy/source/common/network/connection_impl.cc:183] [C2176] closing socket: 0
[2019-05-13 18:27:57.198][26][debug][connection] [external/envoy/source/common/network/connection_impl.cc:502] [C2175] remote close

Red herring that one, looking over a longer window shows that these UC's on these very low traffic apps in preprod go up and down though out the day.

@howardjohn asked me to scale istio-pilot to 0 in preprod to see what happened
Here you can see it scaling down and the pushes stopping:

But in the same window, UC errors persist:

Hi,
We've discovered something else interesting today with regards to Connection: keep-alive headers.
Take the following setup:
[consumer-gateway | envoy] -> [envoy | sauron-seo-app]`
If I curl the sauron-seo-app on localhost (cutting out envoy) I correctly get back the Connection: keep-alive headers indicating to the client that the connection can be kept alive, as you'd expect:
[atcloud@sauron-seo-app-6f449d5795-x9g82 app]$ curl -s -v -o /dev/null http://<IP_ADDRESS>:8080/cars/bmw
* About to connect() to <IP_ADDRESS> port 8080 (#0)
*   Trying <IP_ADDRESS>...
* Connected to <IP_ADDRESS> (<IP_ADDRESS>) port 8080 (#0)
> GET /cars/bmw HTTP/1.1
> User-Agent: curl/7.29.0
> Host: <IP_ADDRESS>:8080
> Accept: */*
>
< HTTP/1.1 200 OK
< X-Powered-By: Express
< Cache-Control: max-age=300
< Content-Type: text/html; charset=utf-8
< Content-Length: 319401
< ETag: W/"4dfa9-p62Vws25oYvDohb0eYlcYQDeduk"
< Vary: Accept-Encoding
< Date: Tue, 14 May 2019 14:24:46 GMT
< Connection: keep-alive
<
{ [data not shown]
* Connection #0 to host <IP_ADDRESS> left intact

However, making the same request from the consumer-gateway pod, results in no keep alive:
[atcloud@consumer-gateway-6c778d487c-tms9b app]$ curl -s -v -o /dev/null http://app.sauron-seo-app/cars/bmw
* About to connect() to app.sauron-seo-app port 80 (#0)
*   Trying <IP_ADDRESS>...
* Connected to app.sauron-seo-app (<IP_ADDRESS>) port 80 (#0)
> GET /cars/bmw HTTP/1.1
> User-Agent: curl/7.29.0
> Host: app.sauron-seo-app
> Accept: */*
>
< HTTP/1.1 200 OK
< x-powered-by: Express
< cache-control: max-age=300
< content-type: text/html; charset=utf-8
< content-length: 319401
< etag: W/"4dfa9-p62Vws25oYvDohb0eYlcYQDeduk"
< vary: Accept-Encoding
< date: Tue, 14 May 2019 14:25:35 GMT
< x-envoy-upstream-service-time: 9
< server: envoy
<
{ [data not shown]
* Connection #0 to host app.sauron-seo-app left intact

So when envoy is in play, keep alive header is being removed.

Hi All.
I did a packet capture on the envoy sidecar of an application we're seeing the UC errors on.  If I'm reading it correctly, it seems to show the traffic come from consumer-gateway (source pod), get intercepted by istio proxy and then a response comes from istio proxy on seo-gateway (destination-app) back to consumer-gateway with an ACK, quickly followed by a TCP reset.
I may heva got this wrong
Here's a snippet of the capture

I may have gotten this wrong as I'm new to the networking of the istio sidecar.  This may be of no use but I thought I'd include it against this issue in case it means anything to anyone.
Cheers
Chris

Something I've noticed by the way; make sure you set mixer.adapters.prometheusmetricsExpiryDuration to something like 6h, otherwise the default is 10m and you'll lose 503's caused by UC's as they're quite intermittent (cc @douglas-reid).
Here's the increase for us over the last 3 hours:

CDS Pushes vs UC's:

Interesting read https://github.com/envoyproxy/envoy/issues/3028

apiVersion: apps/v1
kind: Deployment
metadata:
  name: fortio-server
spec:
  selector:
    matchLabels:
      app: fortio-server
  template:
    metadata:
      labels:
        app: fortio-server
    spec:
      containers:
      - name: fortio-server
        image: fortio/fortio
        # image: paulbouwer/hello-kubernetes:1.5
        resources:
          limits:
            memory: "128Mi"
            cpu: "500m"
        ports:
        - containerPort: 8080
---
apiVersion: v1
kind: Service
metadata:
  name: fortio-server
spec:
  selector:
    app: fortio-server
  ports:
  - name: http
    port: 80
    targetPort: 8080
---
apiVersion: apps/v1
kind: Deployment
metadata:
  name: fortio-client
spec:
  selector:
    matchLabels:
      app: fortio-client
  template:
    metadata:
      labels:
        app: fortio-client
    spec:
      containers:
      - name: fortio-client
        image: fortio/fortio
        args:
          - load
          - -t
          - "0"
          - -c
          - "10"
          - -qps
          - "100"
          - http://fortio-server/
        resources:
          limits:
            memory: "128Mi"
            cpu: "500m"

I deployed 20 replicas of each. In steady state all is good, when I bounce all of the servers I see the huge spikes (consistently). Bouncing the clients does nothing.
@silentdai @PiotrSikora  @Stono

The new data is very useful.  Thanks everyone.
@silentdai is working on the Envoy aspects of this, but I think we can't entirely put this on Envoy.  Envoy does not know about these cluster lifecycle events ahead of time unless the control plane tells it.  Without that knowledge Envoy has to react and retry.    I think the best we can do there is merge https://github.com/envoyproxy/envoy/pull/6578 (@silentdai I think we are waiting for you to give @Stono an image to try, please give us an update on that) and use retries for the remaining cases.  There may be additional bugs in this area, but expect there to always be some retries.   As I've argued previously, there are cases in networking where retries are the only thing that can be done and they shouldn't necessarily be viewed as a bad thing.  Still, we do need to eliminate unnecessary causes of retries and I think that Envoy PR will help with that.
Much more recently, @philrud has started looking into the control plane aspects of this.  Please bear with him since he's just getting started. @philrud is really going to try to understand how cluster lifecycle events produce 503s (e.g,. autoscaling up/down in a hurry, various upgrade scenarios), write more distributed systemsy integration/stress tests around this, and see if we can improve ordering so Envoy is less likely to have to react to 503s in the first place.   I think this effort will start producing results soon, but overall is a many month project.
So both of them are working on this, but please be kind to them.  I hear the frustration (mostly evident on other issues like https://github.com/istio/istio/issues/9113 and https://github.com/istio/istio/issues/14075), but understand that they are trying to help and their effectiveness will be diminished if too much unhappiness is directed their way.
Thank you

@duderino I can also take any test image to help out here :-)

Hi,
I have already tried the build with https://github.com/envoyproxy/envoy/pull/6578 and it made no difference unfortunately.
Cluster lifecycle events aren't a huge concern for me; ironically we are able to do application rollouts without any 503 or UC's (see https://github.com/istio/istio/issues/12183).  Fortio etc will always show 503's during server restarts because the servers won't be gracefully draining connections and you have a race condition between envoy and the server (which we mitigate with a preStop hook).
It's 503s caused by UCs during normal operation that worry me, where there are no associated lifecycle events, source a source envoy unable to read from a destination envoy and needing to retry to the next candidate.

I hear the frustration (mostly evident on other issues like #9113 and #14075)

I understand, and frankly yeah we are frustrated but will try to tone it down and be more considerate.
All I ask in is for is to keep us updated with progress.  It's extremely difficult to see people actively talking about features, developments of new features in 1.2 etc but four days of silence on an issue which is really quite severe.

As an FYI; as I mentioned earlier one we had issues with clients that were doing their own connection pooling, it was getting to a point where it reached its connection pool limit and then was dying.  My theory was that those clients pooling connections were holding onto connections that had otherwise been UC'd and then those connections weren't being released.
In one of those clients we implemented https://hc.apache.org/httpcomponents-core-ga/httpcore/apidocs/org/apache/http/impl/NoConnectionReuseStrategy.html, and we haven't had any problems with that application since.
This was an application which has been migrated to istio, and works fine on the old infra.
I'm not sure what this tells us, but it does all feel related.

@silentdai @duderino @howardjohn I have 0 503s if i disable connection reuse:
DestinationRule:
  spec:
    host: app
    trafficPolicy:
      connectionPool:
        http:
          maxRequestsPerConnection: 1

Previously we were running with 1024.  Obviously this isn't a solution, as it more than doubles the CPU overhead for the sidecar, but it does point the finger at the connection between the source and destination envoy not being kept alive/reusable.

Digging into this more, this PR by @rshriram defaults maxRequestsPerConnection: 1 which is probably why you don't see 503's on a default istio install, and why we are seeing them with maxRequestsPerConnection anything above around 10.

Apologies that pr was never merged

maxRequestsPerConnection is indicating always use the new connection between source envoy and dest envoy. There is no connection pool so the connection disconnected won't bite the following requests.
The image I provided should prevent a connection reuse when the connection is disconnected. Still unknown why it didn't work.
The next thing we should explore is how the connection is broken. In https://github.com/kubernetes/client-go/issues/527#issuecomment-454255493 it was because of components other than istio(ELB). It could be something else in @Stono 's case.

As @Stono is changing maxRequestsPerConnection: Are you seeing UC rate variation?

@silentdai we've settled on around 3 at the moment, which gives us very few UC's.
As for my environment it's GKE v1.12.7-gke.10 with NetworkPolicy enabled.

There is one source of 503 from https://github.com/istio/istio/issues/13848#issuecomment-489765188
[2019-05-06 20:22:57.559][30][debug][connection] [external/envoy/source/common/network/connection_impl.cc:461] [C19040] remote early close

We need the context of C19040, for example:

What is the remote of the C19040, is it another envoy or app?
Is the remote endpoint closing the connection, or an NAT/ELB in between reset the connection?

In my case it's always another envoy, everything is on the mesh.  Traffic never leaves the cluster.

OK I need to head off for the evening but just to update where we're at, our DestinationRule now looks like this on all services we saw the most UCs on:
    host: app
    trafficPolicy:
      connectionPool:
        http:
          http1MaxPendingRequests: 1024
          http2MaxRequests: 10240
          idleTimeout: 4m
          maxRequestsPerConnection: 4
        tcp:
          maxConnections: 10240
          tcpKeepalive:
            interval: 1m
            time: 3m

We haven't seen any in 30 minutes now so that's a marked improvement.  Will leave that in place over the weekend and report back.  Downside is istio-proxy cpu usage is up due to less connection reuse.

Suppose you are using iptables
What are the below values at your side? Both src and dest pod.
$ cat /proc/sys/net/netfilter/nf_conntrack_tcp_timeout_established
$ cat /proc/sys/net/netfilter/nf_conntrack_generic_timeout

So I've been doing a lot more digging with envoy metrics to try and get to the bottom of this now.
I've just correlated a 503UC to this event envoy_cluster_upstream_cx_destroy_local_with_active_rq on the source app, and it seemed to coinside with a envoy_cluster_membership_change.
In this particular example: consumer-gateway -> sauron-seo-app

Maybe the envoy_cluster_membership_change was a red herring as it just happened again with envoy_cluster_upstream_cx_destroy_local_with_active_rq, but no envoy_cluster_membership_change:

Reading the envoy docs https://www.envoyproxy.io/docs/envoy/latest/configuration/cluster_manager/cluster_stats, envoy_cluster_upstream_cx_destroy_local_with_active_rq quite worryingly reads "Total connections destroyed locally with 1+ active request".
connections destroyed with active requests!
But it does explain why in https://github.com/istio/istio/issues/13851 i saw a 503 mid request.

With nf_conntrack_generic_timeout=600 NAT should not reset the connection between gateway-envoy and seo-envoy, as the idleTimeout is lower than 600s.
Let me see if we can verify the idle timeout is activated.

TBH if you had maxRequestsPerConnection not set (so basically permanent connection pooling) and nf_conntrack_generic_timeout was the issue, we'd see UC's every 600seconds, but we don't :-)

Could you save the source envoy and dst envoy config somewhere?
kubectl -n <SRC_POD_NAMESPACE> exec -it  <SRC_POD_NAME> -c istio-proxy -- curl localhost:15000/config_dump

and the dst pod.
My concern is that pilot would interpret infinite timeout as as hard-coded number instead a infinitity_max. I see this pattern a lot.

idle timeout definitely works btw, you can see here where i set it to a low value (30s) and as a result get more connections into the app

I've sent you the config dumps on slack

That shouldn't be good. IIUC active request should remain the same while the connection rate is higher

Yes that's what you can see there; connection rate goes up active requests stay around the same, 15s sample rate.

https://www.google.com/search?q=envoy+lots+of+"upstream_cx_destroy_local_with_active_rq"&oq=envoy+lots+of+"upstream_cx_destroy_local_with_active_rq"&aqs=chrome..69i57.4686j0j7&sourceid=chrome&ie=UTF-8

Update: Unfortunately I didn't reproduce. I have some clue in my experiment.
What we should expect with the above configs

established connection between client envoy and server envoy.
Between the client sidecar envoy and server envoy: at least one established connection. Initially created when the client app create the first request.
When the connection is closed?
It could have multiple causes. The consequences vary a lot. I cannot enumerate all.

idletimeout: client envoy would close the client. As the connection is idle no request should be on the wire. Client envoy will close the connection.
Force close by server envoy. If there is no request on the wire, the next request from client should not see 503. Of course it is 503 if there is data on the wire. Envoy doesn't use pipeline on http 1.1 so at most 1 request is affected.
Health check to server envoy failure. I see this from the code. It's a source of UC503. I would rather to prevent a failed health check instead of dig into the exact behaviors after hitting that failure.

@Stono We should not see "remote early close" unless the service is jeopardized. That's indicating expect further data when the connection is closed. We shouldn't see this as you describe it as low rps. Is there any evidence that client(xx-gateway) or the server(seo) is overloaded at the UC 503?

That's a shame.  I've had 475 in the last 24 hours (on 112,626,354 requests, across 410 envoys):

It's nothing to do with the application being overloaded (it really isn't), in fact two of our top offenders have very littler requests per second (6).  We've also demonstrated that the issue is between source envoy and destination envoy, not between destination envoy and destination app.
I don't know if it helps debug at all, but here are some envoy graphs for the two top offenders:
sauron-seo-app:

sauron-graphql-server:

And the another app which gets consistently quite a bit more traffic, but has had no UC's (search-one):

They're all running with the same Destinationrule configuration:
  spec:
    host: app
    trafficPolicy:
      connectionPool:
        http:
          http1MaxPendingRequests: 1024
          http2MaxRequests: 10240
          idleTimeout: 30m
        tcp:
          maxConnections: 10240
          tcpKeepalive:
            interval: 30s
            time: 30s

I think the key take away of this issue is that you're not going to be able to replicate the incredible diverse setup of each of your customers environments, but your customers are going to experience issues.
I think the focus should be around providing tooling, debugging capability, better metrics (cc @douglas-reid), improved logging and so on in order to help diagnose issues.

@Stono This is a bit hard to digest, but if there are metrics that would help further, i'd love to brainstorm on their generation.

We see more of these as connections ramp up.
Following a deployment, here are the 503s:

And here is the connections TO the envoy in front of sauron-seo-app:

And again:

@Stono could you provide logs from all involved peers (i.e. source app, source Envoy, destination Envoy, destination app) for the same 503 UC event (with a few minutes of logs before and after for context)? I'm trying to figure out which connection is terminated first and starts the chain of errors, but it's unclear from the small pieces of logs from different events, and I couldn't find any event with logs from multiple peers.
You're saying that the issue is between sidecars:

I thought we had also demonstrated that the issue is between source envoy and destination envoy, not between destination envoy and destination app?

But in the logs that you provided, the destination Envoy sees an upstream connection (i.e. connection to the destination app) being reset:

[2019-05-06 20:22:57.559][30][debug][router] [external/envoy/source/common/router/router.cc:644] [C17068][S9430344543646919123] upstream reset: reset reason connection termination

Similarly, the tcpdump that @chrismckean captured shows that the destination app resets connection to the destination Envoy, doesn't it?
Which suggests that the issue is with the connection to the destination app, and not between sidecars.

@PiotrSikora i'm sorry but i'm not spending another whole day grabbing logs.
I've provided ridiculous amounts of information to numerous people on this issue, other issues, via slack etc.
Please let's just get on this call later and live debug together.  You'll be able to ask questions and we can answer them real time.

Hello,
We have the same issue, i read all opened tickets about this. One thing is that we don't use sidecar, we notice some sporadic 503's (mostly from our external monitoring tool). we were using istio 1.0.2 for some time now.
I installed 1.1.7 yesterday and we still have this issue, logs from istio-ingressgateway:
{"log":"[2019-05-29T11:48:56.105Z] \"GET / HTTP/1.1\" 503 UC \"-\" 0 95 288 - \"<IP_ADDRESS>\" \"Go-http-client/1.1\" \"0bede68c-a8a3-4d84-a8e9-1b0ea9f21beb\" \"npm.deez.re\" \"<IP_ADDRESS>:4873\" outbound|4873||verdaccio.coreinfra.svc.dev.kubernetes - <IP_ADDRESS>:80 <IP_ADDRESS>:54740 -\n","stream":"stdout","time":"2019-05-29T11:49:03.638779538Z"}
it happens for others services/apps as well when using istio.
NodePort services (not using the ingress) doesn't have this issue
We ran tests all nights:
curl on pod directly => 200 only
curl on ingress => some 503
Istio was installed with these:
helm template install/kubernetes/helm/istio --name istio --namespace istio-system --set global.proxy.accessLogFile="/dev/stdout" --set global.proxy.clusterDomain=preprod.kubernetes --set prometheus.service.nodePort.enabled=true --set sidecarInjectorWebhook.enabled=false --set global.proxy.includeIPRanges=<IP_ADDRESS>/16 --set gateways.istio-ingressgateway.type=NodePort --set gateways.istio-ingressgateway.autoscaleMin=2 --set pilot.autoscaleMin=2 --set gateways.istio-ingressgateway.nodeSelector.node-role\\.kubernetes\\.io/master=\"true\" > istio1.1.7.yaml
If you have any questions, i'd like to fix this asap
thanks

Some more logs in debug:
"log":"[2019-05-29 15:32:47.807][182][debug][upstream] [external/envoy/source/common/upstream/cluster_manager_impl.cc:1129] **no healthy host for HTTP connection pool**\n","stream":"stderr","time":"2019-05-29T15:32:47.807683175Z"}
{"log":"[2019-05-29 15:32:47.807][182][debug][http] [external/envoy/source/common/http/async_client_impl.cc:94] async http request response headers (end_stream=false):\n","stream":"stderr","time":"2019-05-29T15:32:47.807691662Z"}
{"log":"':status', '503'\n","stream":"stderr","time":"2019-05-29T15:32:47.807717111Z"}
{"log":"'content-length', '19'\n","stream":"stderr","time":"2019-05-29T15:32:47.807726288Z"}
{"log":"'content-type', 'text/plain'\n","stream":"stderr","time":"2019-05-29T15:32:47.807732686Z"}
{"log":"\n","stream":"stderr","time":"2019-05-29T15:32:47.807738813Z"}
{"log":"[2019-05-29 15:32:47.807][182][trace][http] [external/envoy/source/common/http/async_client_impl.cc:102] async http request response data (length=19 end_stream=true)\n","stream":"stderr","time":"2019-05-29T15:32:47.80774496Z"}
{"log":"[2019-05-29 15:32:47.854][187][debug][main] [external/envoy/source/server/connection_handler_impl.cc:257] [C941004] new connection\n","stream":"stderr","time":"2019-05-29T15:32:47.854635313Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][connection] [external/envoy/source/common/network/connection_impl.cc:440] [C941004] socket event: 3\n","stream":"stderr","time":"2019-05-29T15:32:47.854659785Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][connection] [external/envoy/source/common/network/connection_impl.cc:508] [C941004] write ready\n","stream":"stderr","time":"2019-05-29T15:32:47.854667128Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][connection] [external/envoy/source/common/network/connection_impl.cc:478] [C941004] read ready\n","stream":"stderr","time":"2019-05-29T15:32:47.854673563Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:23] [C941004] read returns: 177\n","stream":"stderr","time":"2019-05-29T15:32:47.854679934Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:37] **[C941004] read error: Resource temporarily unavailable**\n","stream":"stderr","time":"2019-05-29T15:32:47.854686252Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:363] [C941004] parsing 177 bytes\n","stream":"stderr","time":"2019-05-29T15:32:47.854692705Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:476] [C941004] message begin\n","stream":"stderr","time":"2019-05-29T15:32:47.854701344Z"}
{"log":"[2019-05-29 15:32:47.854][187][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:243] [C941004] new stream\n","stream":"stderr","time":"2019-05-29T15:32:47.854744225Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:331] [C941004] completed header: key=Host value=rundeck-cac.deez.re\n","stream":"stderr","time":"2019-05-29T15:32:47.854769334Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:331] [C941004] completed header: key=User-Agent value=Go-http-client/1.1\n","stream":"stderr","time":"2019-05-29T15:32:47.854777073
Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:331] [C941004] completed header: key=Referer value=http://rundeck-cac.deez.re/user/login\n","stream":"stderr","time":"2019-05-29T15
:32:47.854783338Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:331] [C941004] completed header: key=Accept-Encoding value=gzip\n","stream":"stderr","time":"2019-05-29T15:32:47.854789387Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:442] [C941004] headers complete\n","stream":"stderr","time":"2019-05-29T15:32:47.854795349Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:331] [C941004] completed header: key=Connection value=close\n","stream":"stderr","time":"2019-05-29T15:32:47.854801091Z"}
{"log":"[2019-05-29 15:32:47.854][187][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:463] [C941004] message complete\n","stream":"stderr","time":"2019-05-29T15:32:47.854806925Z"}
{"log":"[2019-05-29 15:32:47.854][187][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:580] [C941004][S14732545832523136882] request headers complete (end_stream=true):\n","stream":"stderr","time":"2019-05-29T15:32:47
.854824358Z"}
{"log":"':authority', 'rundeck-cac.deez.re'\n","stream":"stderr","time":"2019-05-29T15:32:47.854834945Z"}
{"log":"':path', '/user/login'\n","stream":"stderr","time":"2019-05-29T15:32:47.854841069Z"}
{"log":"':method', 'GET'\n","stream":"stderr","time":"2019-05-29T15:32:47.85484644Z"}
{"log":"'user-agent', 'Go-http-client/1.1'\n","stream":"stderr","time":"2019-05-29T15:32:47.854851924Z"}
{"log":"'referer', 'http://rundeck-cac.deez.re/user/login'\n","stream":"stderr","time":"2019-05-29T15:32:47.854857273Z"}
{"log":"'accept-encoding', 'gzip'\n","stream":"stderr","time":"2019-05-29T15:32:47.854862577Z"}
{"log":"'connection', 'close'\n","stream":"stderr","time":"2019-05-29T15:32:47.854867935Z"}
{"log":"\n","stream":"stderr","time":"2019-05-29T15:32:47.854873194Z"}

Also noting this few lines after:
{"log":"[2019-05-29 15:32:47.855][187][debug][pool] [external/envoy/source/common/http/conn_pool_base.cc:20] queueing request due to no available connections\n","stream":"stderr","time":"2019-05-29T15:32:47.855184357Z"}

https://github.com/istio/envoy/pull/73 fixes the known issue. PR in testing.
tl;dr envoy could use the half close connection talking to upstream and respond 503 to downstream

Along with silentdai's PR, we also discovered that applications which have a low socket timeout value will terminate connections to envoy more frequently, exacerbating the issue.  I've written about it here: https://karlstoney.com/2019/05/31/istio-503s-ucs-and-tcp-fun-times
The TLDR; here is that @silentdai's update (hopefully in 1.1.8) combined with an awareness and adjustment of applications with low tcp socket timeouts resolves 99.99% of our 503's.
I'm going to close this issue now as it's become a bit of a novel, I'm thankful to the whole Istio team for their efforts helping get to the bottom of this one and I know there are more improvements to come from them.

I have come through both "timeout" and "upstream disconnect/reset" errors, which compose about 2% of all requests. I have no idea if we are going into the same problem. What's annoying, the "timeout" requests could be referred from the log of envoy while the "upstream disconnect" could not.

Do you have node.js application behind envoy?
Node.js has 5 sec default connection idleTimeout, and envoy has the same one.
In rare time it generate this error - envoy send reqest in the moment when nodejs closing it.
We have resolve this with  DestinationRule:
apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  name: qqq-destination-rule
spec:
  host: qqq.aaa.svc.cluster.local
  trafficPolicy:
    connectionPool:
      http:
        idleTimeout: 3s
        maxRetries: 3

Thanks for all the info @Stono; You mentioned 1.1.8 will (hopefully) have the fix for the UC 503s, I wondered if you have a link to that PR as I'm interested in the solution?
The reason I ask is because we originally solved the issue by turning on envoy retries with x-envoy-max-retries: 10; x-envoy-retry-on: gateway-error,connect-failure,refused-stream which worked fine.
However, we've since had a few incidents in production whereby a third party service times out and we end up creating massive cascading request chains in production (our Nodejs app also performs retries to third parties which compounds the issue 🤦♂).
We therefore have no choice but to disable envoy retries but before we do this I wanted to check whether the 1.1.8 fix solved the underlying issue or if we should expect to see the UC 503s again?

Node.js has 5 sec default connection idleTimeout, and envoy has the same one.

@turbotankist which version of istio are you using? The default idle timeout in Destination Rule is 1 hour after 1.4.

Apologies for commenting on this long-closed issue, but I was also experiencing this problem (w/ 1.15). Because some of our traffic comes in via NodePorts directly to the service, there's no outbound rule that I can set for retries, so I ended up adding this EnvoyFilter, which retries upstream reset connections rather than expecting the client to do so:
apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: passthrough-retries
  namespace: myapp
spec:
  workloadSelector:
    labels:
      app: myapp
  configPatches:
  - applyTo: HTTP_ROUTE
    match:
      context: SIDECAR_INBOUND
      listener:
        portNumber: 8080
        filterChain:
          filter:
            name: "envoy.filters.network.http_connection_manager"
            subFilter:
              name: "envoy.filters.http.router"
    patch:
      operation: MERGE
      value:
        route:
          retry_policy:
            retry_back_off:
              base_interval: 10ms
            retry_on: reset
            num_retries: 2

After applying ☝🏻 to my service, the random 503/UC errors seem to have gone away regardless of the client or ingress method.
Hopefully this is helpful to someone!


[BUG] syslog is full of kubelet rpc error DeadlineExceeded from cat /var/run/ganesha.pid

Describe the bug
Error message has many errors
Apr  5 09:44:33 dgx22 kubelet[3280794]: E0405 09:44:33.761988 3280794 remote_runtime.go:394] "ExecSync cmd from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="92b89ef7a32ab36a75131cbd9bd8ce3c4bbd3596b6032230e48b64c850637978" cmd=[sh -c ls /data/longhorn && /data/longhorn version --client-only]

and
Apr  5 09:44:40 dgx22 kubelet[3280794]: E0405 09:44:35.932339 3280794 remote_runtime.go:394] "ExecSync cmd from runtime service failed" err="rpc error: code = DeadlineExceeded desc = context deadline exceeded" containerID="01ac86a4d21685ace78e0be702475dba96ec9eb3afe303d655c890f509dafb12" cmd=[cat /var/run/ganesha.pid]

To Reproduce
Steps to reproduce the behavior:

Install k8s 1.22.8
Install longhorn 1.2.4
Allow to run for five days
See error

Also seeing large amount of TCP SYN Retransmits on this node dgx22
Expected behavior
Syslog is error free
Log or Support bundle
If applicable, add the Longhorn managers' log or support bundle when the issue happens.
You can generate a Support Bundle using the link at the footer of the Longhorn UI.
TBA
Environment

Longhorn version: v1.2.4
Installation method (e.g. Rancher Catalog App/Helm/Kubectl): helm
Kubernetes distro (e.g. RKE/K3s/EKS/OpenShift) and version: 1.22.8

Number of management node in the cluster: 1
Number of worker node in the cluster: 2

Node config

OS type and version: DGX / Ubuntu 20.04
CPU per node: 24
Memory per node: 512GB
Disk type(e.g. SSD/NVMe): NVMe
Network bandwidth between the nodes: 40 Gbps

Underlying Infrastructure (e.g. on AWS/GCE, EKS/GKE, VMWare/KVM, Baremetal): Baremetal
Number of Longhorn volumes in the cluster: 3

Additional context
Fresh Longhorn install, there were some flannel issues yesterday and it may be caused by the CNI being in a bad way
Cannot recover by restarting each of the pods one by one on that machine.
FYI (note IP of <IP_ADDRESS> is fake)
kubectl describe node dgx22
Name:               dgx22
Roles:              <none>
Labels:             beta.kubernetes.io/arch=amd64
                    beta.kubernetes.io/os=linux
                    kubernetes.io/arch=amd64
                    kubernetes.io/hostname=dgx22
                    kubernetes.io/os=linux
Annotations:        csi.volume.kubernetes.io/nodeid: {"csi.storageos.com":"b2472df0-b84e-408a-9871-7c934d81fff9","driver.longhorn.io":"dgx22"}
                    flannel.alpha.coreos.com/backend-data: {"VNI":1,"VtepMAC":"1a:97:ac:67:47:87"}
                    flannel.alpha.coreos.com/backend-type: vxlan
                    flannel.alpha.coreos.com/kube-subnet-manager: true
                    flannel.alpha.coreos.com/public-ip: <IP_ADDRESS>
                    kubeadm.alpha.kubernetes.io/cri-socket: /var/run/dockershim.sock
                    node.alpha.kubernetes.io/ttl: 0
                    volumes.kubernetes.io/controller-managed-attach-detach: true
CreationTimestamp:  Thu, 13 May 2021 15:20:58 +0930
Taints:             <none>
Unschedulable:      false
Lease:
  HolderIdentity:  dgx22
  AcquireTime:     <unset>
  RenewTime:       Tue, 05 Apr 2022 09:52:17 +0930
Conditions:
  Type                 Status  LastHeartbeatTime                 LastTransitionTime                Reason                       Message
  ----                 ------  -----------------                 ------------------                ------                       -------
  NetworkUnavailable   False   Mon, 04 Apr 2022 13:55:23 +0930   Mon, 04 Apr 2022 13:55:23 +0930   FlannelIsUp                  Flannel is running on this node
  MemoryPressure       False   Tue, 05 Apr 2022 09:47:17 +0930   Thu, 24 Mar 2022 11:06:26 +1030   KubeletHasSufficientMemory   kubelet has sufficient memory available
  DiskPressure         False   Tue, 05 Apr 2022 09:47:17 +0930   Thu, 24 Mar 2022 11:06:26 +1030   KubeletHasNoDiskPressure     kubelet has no disk pressure
  PIDPressure          False   Tue, 05 Apr 2022 09:47:17 +0930   Thu, 24 Mar 2022 11:06:26 +1030   KubeletHasSufficientPID      kubelet has sufficient PID available
  Ready                True    Tue, 05 Apr 2022 09:47:17 +0930   Fri, 01 Apr 2022 11:48:54 +1030   KubeletReady                 kubelet is posting ready status. AppArmor enabled
Addresses:
  InternalIP:  <IP_ADDRESS>
  Hostname:    dgx22
Capacity:
  cpu:                96
  ephemeral-storage:  920503100Ki
  hugepages-1Gi:      0
  hugepages-2Mi:      0
  memory:<PHONE_NUMBER>Ki
  nvidia.com/gpu:     16
  pods:               110
Allocatable:
  cpu:                96
  ephemeral-storage:<PHONE_NUMBER>56
  hugepages-1Gi:      0
  hugepages-2Mi:      0
  memory:<PHONE_NUMBER>Ki
  nvidia.com/gpu:     16
  pods:               110
System Info:
  Machine ID:                 588332fc3f704dce999047396f7458ad
  System UUID:                04018120-bf02-1647-0000-000300000000
  Boot ID:                    9d1c699f-4432-468f-a597-df144cc976dc
  Kernel Version:             5.4.0-73-generic
  OS Image:                   Ubuntu 20.04.2 LTS
  Operating System:           linux
  Architecture:               amd64
  Container Runtime Version:  docker://19.3.14
  Kubelet Version:            v1.22.8
  Kube-Proxy Version:         v1.22.8
PodCIDR:                      <IP_ADDRESS>/24
PodCIDRs:                     <IP_ADDRESS>/24
Non-terminated Pods:          (22 in total)
  Namespace                   Name                                                      CPU Requests  CPU Limits  Memory Requests  Memory Limits  Age
  ---------                   ----                                                      ------------  ----------  ---------------  -------------  ---
  aiml-chin-research          transfer-data-pittsburgh250k-1--1-4brg5                   1 (1%)        1 (1%)      1Gi (0%)         4Gi (0%)       29m
  aiml-lingqiao-research      yutong-trainer3--1-wnxnx                                  6 (6%)        6 (6%)      64Gi (4%)        64Gi (4%)      123m
  default                     dcgm-exporter-1620886763-kh75r                            0 (0%)        0 (0%)      0 (0%)           0 (0%)         147d
  kube-system                 kube-flannel-ds-8v28x                                     100m (0%)     500m (0%)   50Mi (0%)        250Mi (0%)     19h
  kube-system                 kube-proxy-5cnk2                                          0 (0%)        0 (0%)      0 (0%)           0 (0%)         14d
  kube-system                 nvidia-device-plugin-1620886451-x9c5h                     0 (0%)        0 (0%)      0 (0%)           0 (0%)         326d
  kubernetes-dashboard        dashboard-metrics-scraper-c45b7869d-nh68r                 0 (0%)        0 (0%)      0 (0%)           0 (0%)         5d17h
  kubernetes-dashboard        kubernetes-dashboard-764b4dd7-pwbbc                       0 (0%)        0 (0%)      0 (0%)           0 (0%)         5d17h
  longhorn-system             csi-snapshotter-7565567d77-8dsbw                          0 (0%)        0 (0%)      0 (0%)           0 (0%)         30m
  longhorn-system             engine-image-ei-4dbdb778-m7dw9                            0 (0%)        0 (0%)      0 (0%)           0 (0%)         30m
  longhorn-system             instance-manager-e-67d65bac                               11520m (12%)  0 (0%)      0 (0%)           0 (0%)         31m
  longhorn-system             instance-manager-r-9e1c9de9                               11520m (12%)  0 (0%)      0 (0%)           0 (0%)         31m
  longhorn-system             longhorn-csi-plugin-4plhh                                 0 (0%)        0 (0%)      0 (0%)           0 (0%)         31m
  longhorn-system             longhorn-manager-q6m87                                    0 (0%)        0 (0%)      0 (0%)           0 (0%)         32m
  longhorn-system             share-manager-pvc-7a422177-9466-4ff2-9994-3ae7e30506a5    0 (0%)        0 (0%)      0 (0%)           0 (0%)         29m
  longhorn-system             share-manager-pvc-c8a42bc6-1716-4131-817b-6ac6224659d4    0 (0%)        0 (0%)      0 (0%)           0 (0%)         29m
  prometheus                  alertmanager-prometheus-kube-prometheus-alertmanager-0    100m (0%)     100m (0%)   250Mi (0%)       50Mi (0%)      5d20h
  prometheus                  prometheus-grafana-5449b6ccc9-fwh6l                       0 (0%)        0 (0%)      0 (0%)           0 (0%)         5d20h
  prometheus                  prometheus-kube-prometheus-operator-85bcb96fcb-sg9qw      0 (0%)        0 (0%)      0 (0%)           0 (0%)         5d20h
  prometheus                  prometheus-kube-state-metrics-77698656df-tpxgn            0 (0%)        0 (0%)      0 (0%)           0 (0%)         5d20h
  prometheus                  prometheus-prometheus-kube-prometheus-prometheus-0        100m (0%)     100m (0%)   50Mi (0%)        50Mi (0%)      5d20h
  prometheus                  prometheus-prometheus-node-exporter-x9ltl                 0 (0%)        0 (0%)      0 (0%)           0 (0%)         5d20h
Allocated resources:
  (Total limits may be over 100 percent, i.e., overcommitted.)
  Resource           Requests      Limits
  --------           --------      ------
  cpu                30340m (31%)  7700m (8%)
  memory             66910Mi (4%)  69982Mi (4%)
  ephemeral-storage  0 (0%)        0 (0%)
  hugepages-1Gi      0 (0%)        0 (0%)
  hugepages-2Mi      0 (0%)        0 (0%)
  nvidia.com/gpu     1             1
Events:              <none>

Sorry for the delay support bundle is attached.
longhorn-support-bundle_385eb4c2-7da8-4c01-973a-e1e72ff05f01_2022-04-06T01-10-37Z.zip


HPX module "configurations"

This issue is for discussing if and how to expose modules to users:

size of modules; small and large?
static/dynamic?
build configurations?

There are a few high-level "natural" levels of features that build on top of each other:

utilities (testing, assertions, configuration, etc.)
thread pools only
synchronization primitives/futures (manual thread pool management, explicitly pass executors to apply/async)
parallel algorithms
local runtime (configuration management, default pool for apply/async)
distributed runtime (including support for components/actions)
distributed synchronization primitives, collectives
distributed parallel algorithms
optional components (already linked separately)

In addition to this users may want to pick smaller modules individually (hpx_concurrency). The question is: can we support both use cases? Can we support both use cases simultaneously (can I link to libhpx_threading ("high-level" module) and libhpx_serialization ("low-level" module)? Is the distinction necessary?
How do we handle build configurations? Should it be possible to individually disable modules? Is it up to the user to ensure that a module's dependencies are all enabled?
Given how complex things could get I'm leaning towards only exposing these "high-level" configurations/libraries to the user.
That's more questions than answers and should get us started...


Jump/call instructions to a pointer considered an undefined label.

Example file:
segment_name SEGMENT USE64
    jmp dword ptr [eax]
segment_name ENDS

"dword" is considered an undefined label.

This bug is also fixed in the version after <IP_ADDRESS>


Add new filer support mongodb

Filer server support MongoDB

very nice! Thanks!
Please also adjust scaffold.go?

I add default config MongoDB to scaffold.go


Add summary of changes for v2.15

Describe your pull request here: This PR add the summary of changes for v2.15
List the file(s) included in this PR: v2_15_0.md
After creating the PR, follow the instructions in the comments.

Seems to be good for API ML.


MWPW-134424 | Center notification buttons are not center aligned

Medium center notification button are not center aligned.
Adding the explicit center aligning for button section in notification center
Resolves: MWPW-134424
Test URLs:

Before: https://main--milo--adobecom.hlx.page/drafts/mathuria/aside/aside?martech=off
After: https://notccenter--milo--aishwaryamathuria.hlx.page/drafts/mathuria/aside/aside?martech=off

Thank you Aishwarya for the fix.
Verified in the below cc fragment and page url :
Before the fix
https://main--cc--adobecom.hlx.page/cc-shared/fragments/seo-articles/get-started-notification-blade

https://www.stage.adobe.com/creativecloud/animation/discover/animation-key-poses.html

After the fix
https://main--cc--adobecom.hlx.page/cc-shared/fragments/seo-articles/get-started-notification-blade?milolibs=notccenter--milo--aishwaryamathuria

https://main--cc--adobecom.hlx.page/creativecloud/animation/discover/cel-animation?milolibs=notccenter--milo--aishwaryamathuria


Update old pocoo.org link to palletsprojects.com

this is a small fix and there were many similar changes...


Move filters drawer to the left; open by default.

Requires tightening up the copy and reducing other spacing

Tried this on the branch miniDrawer. Content reduction required in order to fit into a reasonable width were pretty severe. This also ended up making it more unclear IMO that the filters applied specifically to the left scatterplot, rather than the full interface as the report is no longer hidden while the drawer is opened.
In the future, could revisit this when we have bandwidth to do a broader design exploration.

Just kidding. Figured out how to fix the above issues mostly. Will merge later this week. 🚀


[google-translate] Language does not equal country flag

Extension
https://www.raycast.com/gebeto/translate
Description
Flags are commonly recognized as expressions of national pride; however, using them to signify languages can be highly deceptive. Despite multiple countries sharing identical flags, the linguistic diversity within each nation can be extensive. Depending solely on flags for language representation may result in oversimplifications and misunderstandings, overlooking the intricate nature of global communication.
Who will benefit from this feature?
No response
Anything else?
No response

Yeah, it makes sense

It makes sense, but without flags UI is harder to use, so need to think about some good solution for this one, because showing the country code will also looks not so good. So maybe will be good to show whole language name. But need to check how it will work


Strage GLib.Variant

After some work with DBus I found very strange GLib.Variant as answer to property request via org.freedesktop.DBus.Properties. My variable is metadata:
metadata = props:Get("org.mpris.MediaPlayer2.Player", "Metadata") -- wrapper around DBusProxy
for k,v in metadata:pairs() do print(k,v.value) end -- Everything works fine
print('FAIL HERE')
for k,v in metadata:pairs() do print(k,metadata[k].value) end -- GLib.Variant: no `some field'

Example:
bitrate	128
mpris:artUrl	file:///tmp/clementine-art-UX1706.jpg
mpris:trackid	/org/mpris/MediaPlayer2/Track/43
xesam:artist	lgi.rec 0x7f885c005e90:GLib.Variant
xesam:genre	lgi.rec 0x2882b80:GLib.Variant
xesam:title	The Untouchables - Level 2
xesam:url	http://streaming.rolandradio.net:80/rolandradio
FAIL HERE
/usr/bin/lua: current_mus.lua:33: GLib.Variant: no `bitrate'
stack traceback:
	[C]: in function 'error'
	/home/v/.luarocks/share/lua/5.2/lgi/component.lua:160: in function </home/v/.luarocks/share/lua/5.2/lgi/component.lua:156>
	[C]: in function '__index'
	current_mus.lua:33: in main chunk
	[C]: in function 'dofile'
	/home/v/.luarocks/lib/luarocks/rocks/trepl/scm-1/bin/th:143: in main chunk
	[C]: in ?

Here's prop:Get function:
return self._proxy:call_sync(
	'Get',
	GLib.Variant.new_tuple(
	{
			GLib.Variant("s",interface);
			GLib.Variant("s",property);
	}, 2),
	Gio.DBusConnectionFlags.NONE,
	-1, -- Timeout
	nil -- Cancellable
)

for k,v in metadata:pairs() do print(k,metadata[k].value) end

Correct me if I am wrong, but the docs do not say that the above should work, do they?
https://github.com/pavouk/lgi/blob/master/docs/variant.md#data-access

metadata[k] == v, right?

Your bug report says that this is not the case, so no.
Also, I am pointing at the docs and basically say "I am not sure, but the docs only say something about integer indices". So this is another "no".
Are you perhaps looking for metadata.value[k] (but this only works with string keys, not with integer keys, I think...)?

Yes, it really works using metadata.value[k].  Now ther's another strange moment:
org.freedesktop.DBus.Properties.Get (in STRING interface_name,
                                     in STRING property_name,
                                     out VARIANT value);
org.freedesktop.DBus.Properties.Set (in STRING interface_name,
                                     in STRING property_name,
                                     in VARIANT value);
org.freedesktop.DBus.Properties.GetAll (in STRING interface_name,
                                        out DICT<STRING,VARIANT> props);

Type of Metadata property is also DICT<STRING,VARIANT>. But result of GetAll(...)[1] is table, and result of Get(...)[1] is Variant. Why?

But result of GetAll(...)[1] is table,

It is a table with string keys and Variant values, right? So it is DICT<STRING,VARIANT>.

and result of Get(...)[1] is Variant. Why?

Sorry, what is the question exactly? You quote the documentation that says that Get returns a variant and GetAll returns a mapping from strings to variants and then you ask just why you get these result??
Closing under the assumption that there is no bug here to fix.

I think, I understood... a bit strange for me, but OK.


Initial package organization for garden builds

It is generally going to be easier to keep the license BSD-3-Clause to match the upstream drake implementation I am using as the basis of our new implementation.  I have changed the license and added a credit in the readme to reflect this.

I'm getting the following errors when running bazel build //...
Starting local Bazel server and connecting to it...
ERROR: /home/nkoenig/gz/msgs/BUILD.bazel:94:17: no such package '@com_google_protobuf//': The repository '@com_google_protobuf' could not be resolved: Repository '@com_google_protobuf' is not defined and referenced by '//msgs:gzmsgs_cc_proto'
ERROR: /home/nkoenig/gz/msgs/BUILD.bazel:94:17: every rule of type _gz_msgs_generate_gen implicitly depends upon the target '@com_google_protobuf//:protoc', but this target could not be found because of: no such package '@com_google_protobuf//': The repository '@com_google_protobuf' could not be resolved: Repository '@com_google_protobuf' is not defined
ERROR: Analysis of target '//msgs:gzmsgs_cc_proto' failed; build aborted: Analysis failed
INFO: Elapsed time: 2.151s
INFO: 0 processes.
FAILED: Build did NOT complete successfully (76 packages loaded, 838 targets c\
onfigured)

ERROR: Analysis of target '//msgs:gzmsgs_cc_proto' failed; build aborted: Analysis failed

For this PR, you shouldn't have msgs.  The only repo here should be gz/bazel

I'm getting the following errors when running bazel build //...
Starting local Bazel server and connecting to it...
ERROR: /home/nkoenig/gz/msgs/BUILD.bazel:94:17: no such package '@com_google_protobuf//': The repository '@com_google_protobuf' could not be resolved: Repository '@com_google_protobuf' is not defined and referenced by '//msgs:gzmsgs_cc_proto'
ERROR: /home/nkoenig/gz/msgs/BUILD.bazel:94:17: every rule of type _gz_msgs_generate_gen implicitly depends upon the target '@com_google_protobuf//:protoc', but this target could not be found because of: no such package '@com_google_protobuf//': The repository '@com_google_protobuf' could not be resolved: Repository '@com_google_protobuf' is not defined
ERROR: Analysis of target '//msgs:gzmsgs_cc_proto' failed; build aborted: Analysis failed
INFO: Elapsed time: 2.151s
INFO: 0 processes.
FAILED: Build did NOT complete successfully (76 packages loaded, 838 targets c\
onfigured)

Ahh, I see. thanks.


Toolbar slot fix

Problem
Multi-grid blueprints saved from vanilla SE have any toolbar slots with a block from another subgrid broken due to inconsistent EntityId mapping, unless the MGP plugin is used while producing the blueprint. In that case the EntityId values are correct.
On welding the same terminal block (with slots or the ones associated to slots) the second time from the same projection a new EntityId is assigned if the previous one still exists in the world. The workaround is to power-cycle the projector between welding attempts, but it still breaks in cases where there are already built blocks to be consistent with. This affects mostly missiles built from the repair projection of the whole ship, but can hit any player if welding is interrupted and had to be restarted for some blocks.
Solution
On loading the blueprint find all toolbar slots with assigned blocks and store those associations based on their subgrid index and block location. Build the mapping from the block to the toolbar slot.
After building a terminal block from projection find all terminal blocks (maybe including itself) which has the newly built block in a toolbar slot and fix those slots. Also fix the slots of any blocks with a toolbar right after building them.
Introduce a "Fix toolbars" button on the projector's terminal, so the toolbars can be fixed without having to rebuild the affected blocks.

The solution has been merged into the 0.7.0 release branch, so closing this PR in favor of that.


Add dynamic option creation to dropdown

This allows the user to accept new options to be set on the dropdown field:

It's natively handled by Select2 as you can see into the documentation.
To active the option, we just need to set acceptNewOptions to true:
my_field:
    label: my_label
    type: dropdown
    acceptNewOptions: true

The dropdown expects a list of options which can take two different forms:
value only:
options:
    draft
    published
    archived

or key/value :
options:
    draft: Draft folder
    published: Published folder
    archived: Archived folder

how to deal with the second case when adding a new option/item?

@damsfx Whichever the way you pass the available options to the dropdown, it is initialized with value and label.
In your first case, both values and labels will be the same, in the second the labels are differents from the values that will be sent to the server, but all of that is just front-end sugar.
When Select2 (the library used by the dropdown) add a new key/value pair to it, it just act as your first use case, and that's all we need. Here is an example of value added dynamically.

Of course if you use your second case and dynamically add a value to the dropdown, the dropdown values may seem "weird" like:
Draft folder
Published folder
Archived folder
custom-value

but that's how it work, and it's kind of logic: when you select one of the 1st, 2nd or 3rd label and send it to the server, the browser defines the value associated to it (draft for Draft folder, published for Published folder and so on), but if you send a custom value, you exactly know what you send because key = value.

How is this handled with the get*Options method? Is the custom value merged into that array of options? Would this be supported for type: relation dropdowns? Also, we should probably name it allowCustom instead.

The get*Options method works well with this behavior.
For now it does not merge the value into the array though, because there is no AJAX.
There is a callback that we can override to do some stuff during the addition of the value, it is not intended to to that but it's a possibility. It's designed to modify the value or label before adding it, or change the position of the inserted label into the dropdown.
There is some additional work to be supported by the relationship between dropdowns as you may guess.
The good way to do (I guess) would be to open a popup including the form of the related model to create it dynamically using deferred bindings and then select it.
I could work on this feature later if we decide of how it should work.

@RomainMazB from a UI perspective, I would want to see it show something to indicate that if you type a value that doesn't exist as an existing, it will be added as an option. With your example in your OP, option "c" looks like a legitimate value since it doesn't look any different to options "a" and "b" which do exist.

@bennothommo yeah, I can easily prefix the just created value, this is why the method I may use to send the AJAX request is designed for at its basis: see here

@bennothommo with dropdown "templating" it's possible to add an icon.
In certain circumstances is more useful than a text.

@damsfx yeah that's cool if we use an icon - I was merely suggesting we need something.

Ok: I've made the modifications asked.
I made some test with default AJAX events like dependsOn, it works very well as is!
I made a video to show all the actual behavior.
https://user-images.githubusercontent.com/53976837/119276618-6932ae00-bc1b-11eb-9f57-a0d524d5ea2f.mp4

I agree with @bennothommo that we need something to indicate that custom user provided options are not part of the default set of options, but I'm not sure the plus icon is the way to go hear. Are there any examples of this UX pattern elsewhere in the world that we could pull inspiration from?

The only one that came up to my mind is the github's branch dropdown but it create the branch and reload the page instantly so we can't get inspiration on "how should we make it clear that this tag has just been created on the fly"
https://user-images.githubusercontent.com/53976837/119489207-bf0e6f80-bd5b-11eb-858f-4dbf174d632d.mp4
What could be (easily) done:

Prepend the tag to the list instead of append it
Change the "plus" icon to something else, maybe the terminal icon which is used into component to set custom value to property, or the pencil outline icon:

Increase the left padding
Adds a title attribute which specifies that it has just been created as a custom value

I'm not the most UX-sensible guy so my suggestions are maybe not so accurate

@RomainMazB I've had another look at this. I'm finding it difficult to see the use case. You mentioned here:

There is a callback that we can override to do some stuff during the addition of the value, it is not intended to do that but it's a possibility. It's designed to modify the value or label before adding it, or change the position of the inserted label into the dropdown.

What would the intended use case be for that? Is it the case that people wanting to use this particular allowCustom property will have to set up some sort of handler to save the new option, otherwise it disappears when loading the form again?

No this is not accurate anymore since all the existing form ajax handlers work well without any custom additional stuff.
When I talked about that, I thought we'd have to do something to make dependsOn, trigger, preset and other existing behavior to work, I don't have any use case in my mind that would need more work on this.

@bennothommo
And if you talked about the feature introduced by the PR in general: I have some.
My actual use case is the one you can see in the video: I pre-filled the dropdown with all the Winter's events, but I let the user add some custom event he may have introduced by installed or created a custom plugin. If a custom value is inserted, the next time it will be into the dropdown.
In general, this feature will be used when you have a column that will be filled with the same value most of the time:
You could pre-fill the dropdown with the most used values but also allow custom additional value, that would be then saved and added to the drop-down.
The get*Options method returns the form's model value passed through a unique rule, but you can still add one more:
public function getMeasureNameOptions()
{
    // Prefill the dropdown with the already used values
    $measures = self::query()
                     ->select('measure_name')
                     ->distinct('measure_name')
                     ->get();

    // Insert the actual form's model value to avoid it to vanish
    // on eventual AJAX call that would refresh it (dependsOn)
    if ($this->measure_name) {
        $measures->add(['name' => $this->measure_name]);
    }

    return $measures->pluck('name', 'name');
}

// If a custom values is inserted here, it will be pre-filled on next model creation

With that look in mind, it looks more like an extension of the input type text than dropdown:
At the beginning it could even be empty, and the more you enter custom values, the more you get your dropdown pre-filled with values you may potentially choose without even type on the keyboard.
You could even order the values depending on their occurrence counting on the table.
In the plugin I'm actually working on, I already found two use cases that would increase the UX where the user will use many time the same value but still need to be able to insert a custom one. Without this feature, I'll need:

A switch to select "I want to insert custom value" or "Select an already used value"
A dropdown with the existing values
An input type text to insert custom value
And because I get two fields to set a single column, I'll need to register into the beforeSave event to see on which state was the switch and pick the good field value.

@LukeTowers @bennothommo
Any new thoughts on the appearance that would fit here?
I know you are all busy with more important stuff but I feel like this one just need a pinch to get merged so we can move on.
Let me know if I'm wrong and this feature is definitely unwanted

@RomainMazB is there a PR to the docs providing explanation of how to use this along with the gotchas of what people should do differently for handling options when user defined custom options are available?

@LukeTowers I've just improved the documentation's PR with a full basic example here https://github.com/wintercms/docs/pull/14/commits/0b358397de575c5e8f100f84e114cc83184f3e21

@LukeTowers @bennothommo
Any news on that one? LGTM and is documented, not a BC as it just adds an option to an existing field type.
As a use case, in my sunlab/wn-measures-plugin,
I'm waiting for this PR to introduce a dropdown listing all the modules' native events but with the ability to create "on-the-fly" new event name for the listeners. The video of this is described in this https://github.com/wintercms/winter/pull/151#issuecomment-846624450

@RomainMazB can you merge develop back into your branch and resolve the conflicts / recompile storm? I should be able to review it after that's done and it's probably good to go (although I'll want to tweak the docs PR a bit first too).

👀 What is the status of this?
I could use this functionality

@RomainMazB are you still interested in getting this merged? If not, @AIC-BV are you interested in getting it merged?

TBH, as of today I do not use winter anymore on a daily basis.
I can merge develop back into my branch but I do not have a working installation of winter to test it.
@AIC-BV, if I do the job, could you just test the feature before it get merged?

Fair enough @RomainMazB, I appreciate all your help and support over the years!

Still looks like a great feature to me!
Don't need it straight away but can obviously test it

Implemented in https://github.com/wintercms/winter/commit/bb79834af1690c63cc642af72a560e5f7e0d3c4a. Thanks @RomainMazB!

I added a new option 'Scharnier' but its not in the list.
I was expecting it to be permanently added. Understandable ofcourse since its not in the extraOptions array.
Shouldn't it, ideally, be permanently added to the list?

item:
    tab: Item
    label: Item
    type: dropdown
    emptyOption: -
    options: getExtraOptions
    allowCustom: true

public function getExtraOptions() {
  return [
      'tablet' => 'Tablet',
      'legplank' => 'Legplank'
  ];
}

@AIC-BV This is exactly why I decided to develop another type of formwidget.
https://github.com/Hounddd/wn-selfcomplete-plugin

It works both as a drop-down list (with search on existing values) and as a text field, allowing you to add a value.

@damsfx that's exactly what allowCustom does