This is a question about the "$status" log value when "proxy_read_timeout" occurs.

[박규철]

Hello.

This is a question about the "$status" log value when "proxy_read_timeout"
occurs.
Nginx version in use: v1.25.3

Contents of 1Mbyte size were requested to [Origin Server].
A response up to approximately 500Kbytes in size, including the header, was
received without delay.
However, after 500Kbytes, no response was received from Origin for 3
seconds and the connection (time-out)
Since the message "upstream timed out...while reading upstream" was logged
in the error log, I think the connection was lost due to the
"proxy_read_timeout 3s" setting.

While checking the log, I noticed that the "$status" value in the access
log was different from what I thought.
In my opinion, if the connection was terminated by "proxy_read_timeout",
the "$status" value would be 5xx, but the "$status" value in the saved
access log was 200.

A normal response was not completed due to "proxy_read_timeout", so I would
like to know why the "$status" value is stored as 200 instead of 5xx.
Should I check a variable other than "$status" for responses to abnormal
timeouts such as "proxy_read_timeout"?

Any help is appreciated.

Best regards,
kyucheol


-----

[ config ]
log_format read_log
'[$time_iso8601] '
'$request_time\t'
'$host '
'$request_method '
'$request '
* '$status* '
'$upstream_status '
'$body_bytes_sent '
'$request_id';

server {
      listen 80;
      server_name test.read_timeout.com;
      access_log /etc/nginx/log/$server_name/access.log read_log;

      proxy_cache_valid 200 206 304 1d;
      proxy_connect_timeout   30s;
      proxy_read_timeout      3s;

      proxy_set_header Host testmedia.net;
      proxy_ignore_headers Cache-Control;

      location / {
            proxy_pass http://[Origin server];
      }
}


[ curl request ]
> GET /media3/testfile HTTP/1.1
> User-Agent: curl/7.29.0
> Accept: */*
> Host: test.read_timeout.com
>
< HTTP/1.1 200 OK
< Date: Wed, 10 Jan 2024 08:20:52 GMT
< Content-Type: text/plain
< Content-Length: 1048576
< Connection: keep-alive
< Server: nginx
< Last-Modified: Thu, 17 Aug 2023 12:43:31 GMT
< ETag: "64de15f3-100000"
< Age: 1
< vary: B
< Accept-Ranges: bytes
<
{ [data not shown]
 46 1024k   46  479k    0     0   155k      0  0:00:06  0:00:03  0:00:03
 155k* transfer closed with 557689 bytes remaining to read
 46 1024k   46  479k    0     0   155k      0  0:00:06  0:00:03  0:00:03
 155k
* Closing connection 0
curl: (18) transfer closed with 557689 bytes remaining to read


[ error log ]
2024/01/10 17:20:55 [error] 98285#98285: *1* upstream timed out (110:
Connection timed out) while reading upstream*, client: 127.0.0.1, server:
test.read_timeout.com, request: "GET /media3/testfile HTTP/1.1", ~~~~~~~


[ access log ]
[2024-01-10T17:20:55+09:00] 3.080       test.read_timeout.com GET GET
/media3/testfile HTTP/1.1 *200 *200 490887 45f01510d4ec56f01899c9dea81e7628

-----
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20240116/4abe8f47/attachment.htm>