In access log, some requests's duration is much longer than upstream_service_time

1

Most requests’s duration is nearly the same as upstream_service_time, with a very little difference.
But some requests’s duration is much longer than upstream_service_time, for example the upstream_service_time is 2ms, the duration could be 1200ms. The request’s status code is normal.
Don’t know how to debug such situation…
Here is a sample access log line:
{“downstream_remote_address”:“114.102.184.169:0”,“authority”:“prt-portal:8080”,“path”:"/article/list",“protocol”:“HTTP/1.1”,“duration”:“1092”,“upstream_service_time”:“1”,“upstream_local_address”:“127.0.0.1:47208”,“upstream_transport_failure_reason”:"-",“route_name”:“default”,“downstream_local_address”:“172.16.0.103:8080”,“user_agent”:“Mozilla/5.0 (Windows NT 10.0; WOW64; Trident/7.0; rv:11.0) like Gecko”,“response_code”:“200”,“response_flags”:"-",“start_time”:“2020-08-27T09:33:42.704Z”,“method”:“POST”,“request_id”:“7bb947aa-ffa4-9c95-a16d-6d2a9193fb20”,“upstream_host”:“127.0.0.1:8080”,“x_forwarded_for”:“114.102.184.169”,“requested_server_name”:“outbound_.8080_._.prt-portal.prod.svc.cluster.local”,“bytes_received”:“30”,“istio_policy_status”:"-",“bytes_sent”:“6197”,“upstream_cluster”:“inbound|8080|http-ms|prt-portal.prod.svc.cluster.local”}

1 Like
2

I am also facing similar issue with istio on AKS even for 404 calls

ISTIO version: 1.5.6
AKS: v1.17.13

{
  "authority": "myhost.com",
  "bytes_received": "5854",
  "bytes_sent": "0",
  "downstream_local_address": "10.1.7.237:443",
  "downstream_remote_address": "141.101.76.199:55042",
  "duration": "5001",
  "istio_policy_status": "-",
  "method": "POST",
  "path": "/cve?save=false",
  "protocol": "HTTP/1.1",
  "request_id": "b6da0b58-6634-43f0-9d1d-0620f40d72b4",
  "requested_server_name": "myhost.com",
  "response_code": "404",
  "response_flags": "NR",
  "route_name": "-",
  "start_time": "2021-01-30T20:02:50.216Z",
  "upstream_cluster": "-",
  "upstream_host": "-",
  "upstream_local_address": "-",
  "upstream_service_time": "-",
  "upstream_transport_failure_reason": "-",
  "user_agent": "Go-http-client/2.0",
  "x_forwarded_for": "13.80.251.172,141.101.76.199"
}

We are having JWT policy which is excluded for this path as well.

@ostromart @howardjohn @ianmiell please tag anyone who can help