istio: tiny percentage of 503s on a cluster with no change & @low qps
running 100qps through ingress in the perf setup getting a small % of 503s (only on multi hops - maybe a timeout issue?) - it also only happens with >=20 connections or so
35.199.14.248/fortio2/fortio/fetch/echosrv1:8080/echo
Starting at 100 qps with 30 thread(s) [gomax 2] : exactly 3000, 100 calls each (total 3000 + 0)
Ended after 30.071664869s : 3000 calls. qps=99.762
Sleep times : count 2970 avg 0.26524946 +/- 0.01577 min 0.192739205 max 0.292777981 sum 787.790887
Aggregated Function Time : count 3000 avg 0.037497644 +/- 0.01582 min 0.009672528 max 0.10991789 sum 112.492931
# range, mid point, percentile, count
>= 0.00967253 <= 0.01 , 0.00983626 , 0.03, 1
> 0.01 <= 0.012 , 0.011 , 0.17, 4
> 0.012 <= 0.014 , 0.013 , 0.70, 16
> 0.014 <= 0.016 , 0.015 , 2.63, 58
> 0.016 <= 0.018 , 0.017 , 5.33, 81
> 0.018 <= 0.02 , 0.019 , 8.17, 85
> 0.02 <= 0.025 , 0.0225 , 19.70, 346
> 0.025 <= 0.03 , 0.0275 , 33.83, 424
> 0.03 <= 0.035 , 0.0325 , 52.87, 571
> 0.035 <= 0.04 , 0.0375 , 67.87, 450
> 0.04 <= 0.045 , 0.0425 , 76.67, 264
> 0.045 <= 0.05 , 0.0475 , 82.83, 185
> 0.05 <= 0.06 , 0.055 , 91.00, 245
> 0.06 <= 0.07 , 0.065 , 94.97, 119
> 0.07 <= 0.08 , 0.075 , 98.10, 94
> 0.08 <= 0.09 , 0.085 , 98.87, 23
> 0.09 <= 0.1 , 0.095 , 99.60, 22
> 0.1 <= 0.109918 , 0.104959 , 100.00, 12
# target 50% 0.0342469
# target 75% 0.044053
# target 99% 0.0918182
# target 99.9% 0.107438
Code 200 : 2995 (99.8 %)
Code 503 : 5 (0.2 %)
Response Header Sizes : count 3000 avg 165.72233 +/- 6.772 min 0 max 167 sum 497167
Response Body/Total Sizes : count 3000 avg 166.09833 +/- 2.432 min 165 max 226 sum 498295
Saved result to data/2018-02-08-055310_Fortio.json
All done 3000 calls 37.498 ms avg, 99.8 qps
About this issue
- Original URL
- State: closed
- Created 6 years ago
- Comments: 87 (76 by maintainers)
I have run into this issue as well.
[xxx] [2018-10-02T16:12:44.409Z] "GET /glb HTTP/1.1" 503 UC 0 57 1 - "-" "GoogleHC/1.0" "ecb1c797-a58f-9c53-be4f-857bc2884456" "10.100.0.100" "127.0.0.1:3000"It appears to affect apps running Node/express but not Play.
curl -vindicates that The Node app responds withConnection: keep-alive, but the Play app does not send that response header. The issue seems to go away by settingConnection: closein the response.Hey,
i just ran into what seamed to be the same issue. our system is running ambassador with istio 1.0.5 (mtls enabled) and a node/express server, serving some static files. usually that service gets hit with a few requests in a short burst, and sometimes one of those requests failed with a 503 UC. i’ve added the connection close to the response header and it seams to fix the 503 responses, though i have the same question as @jsw regarding the recommended approach and so forth.
i’d highly appreciate it if someone would take the time to clarify this and maybe it should be documented somewhere?
A trace log for a 503 upstream connection:
This looks weird because envoy read 166 bytes and parsed it. But ended with
resetting 1 pending requests. Will follow the source around codec_impl later.I reproduced this in my env with 0.6.0. I don’t think it related to connection timeout, as in fortio result, the max response was around 140ms, which is way lower than 1s.
In ingress access log: (see here for log format)
The response flag is
-which means the 503 from upstream.In deployment1 sidecar access log:
the response flag is
UC, which meansUpstream connection termination in addition to 503 response code..The 503 is coming from the sidecar, and seems upstream of sidecar (echosrv) is terminating connection.
In sidecar envoy stats (I got total 3 of 503s):
this means the echosrv is terminating the connection while request is still active. Any idea why this happen?
@ldemailly in istio 0.8, i met the same error, tiny percent request, the sidecar envoy returns 503, do not use any rule ,log is below: [2018-07-06T06:11:12.983Z] “POST /api/ HTTP/1.1” 503 UC 16687 57 0 - “-” “Mozilla/5.0 (pc-x86_64-linux-gnu) Siege/4.0.4” “41344284-c914-9db1-a30a-983e74455227” “10.20.10.20:8888” “127.0.0.1:8888” i saw the talk here and in envoy reference, It seems that the problem has not been solved, Is that right?
0.8
The RemoteClose event right after onData will trigger it.
thanks a lot @ldemailly @lizan this is quite a finding!
Now I believe this is an issue at Envoy, filed https://github.com/envoyproxy/envoy/issues/2715.
@PiotrSikora the hope was that while you have a pilot less setup to investigate mtls perf issue, whether you also see 503s during your testing (which would rule out pilot / bad config) and confirm andra’s determination