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>
Hello!
On Tue, Jan 16, 2024 at 01:15:09PM +0900, 박규철 wrote:
> 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"?
The $status variable shows the status as sent to the client in the
response headers. When proxy_read_timeout happens, the response
headers are already sent, so $status contains 200 as sent to the
client.
For errors happened during sending the response body, consider
looking into the error log. Some generic information about
successful request completion might be found in the
$request_completion variable
(http://nginx.org/r/$request_completion). Note though that it
might not be set for variety of reasons.
--
Maxim Dounin
http://mdounin.ru/
Hello.
I came to understand why 200 is stored in the $status variable when
proxy_read_timeout occurs.
Thank you for the reply.
2024년 1월 17일 (수) 오전 7:27, Maxim Dounin <mdounin at mdounin.ru>님이 작성:
> Hello!
>
> On Tue, Jan 16, 2024 at 01:15:09PM +0900, 박규철 wrote:
>
> > 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"?
>
> The $status variable shows the status as sent to the client in the
> response headers. When proxy_read_timeout happens, the response
> headers are already sent, so $status contains 200 as sent to the
> client.
>
> For errors happened during sending the response body, consider
> looking into the error log. Some generic information about
> successful request completion might be found in the
> $request_completion variable
> (http://nginx.org/r/$request_completion). Note though that it
> might not be set for variety of reasons.
>
> --
> Maxim Dounin
> http://mdounin.ru/
> _______________________________________________
> nginx mailing list
> nginx at nginx.org
> https://mailman.nginx.org/mailman/listinfo/nginx
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20240117/dc08aa41/attachment.htm>