Q: Nginx $upstream_response_time returns 2 values

Question

Sometimes Nginx $upstream_response_time returns 2 values.

xxx.xxx.xxx.xxx - - [08/Nov/2017:23:43:25 +0900] "GET /xxxxxxxxxxxx HTTP/2.0" 200 284 "https://xxxxxxxxxxx" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36" "-" "0.015" "0.001, 0.014"

"0.001, 0.014" this is a $upstream_response_time. Why does this has two values?

Log format:

log_format main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" '
                      '"$request_time" "$upstream_response_time"';

Answer 1

Note that this is spelled out in the documentation:

Times of several responses are separated by commas and colons like addresses in the $upstream_addr variable.

This means that it made multiple requests to a backend, most likely you either have a bare proxy_pass host that resolves to different IPs (frequently the case with something like Amazon ELB as an origin), are you have a configured upstream that has multiple servers. Unless disabled, the proxy module will make round robin attempts against all healthy backends. This can be configured from proxy_next_upstream_* directives.

For example if this is not the desired behavior, you can just do:

proxy_next_upstream off;