Strange log entries (upstream time/request_time)

Hi,

I’m running a simple nginx->memcache->backend architecture, and I’m
currently facing some backend problems.

While debugging the situation I’ve run on some strange log entries which
look like nginx was incorrectly giving the summary request_time value :

91.180.100.2 www.mydomain.com “23/Oct/2011:22:30:05 +0200”
“10.1.0.41:11211 : 10.1.0.48:90” “GET /images/footer-simple.gif
HTTP/1.1” 200 (404 : 200) UP_RESPONSE 0.001 : 60.001 request_time
120.004

So, nginx check’s for content in memcache, memcache (10.1.0.41) gives
404 in less than 1ms, then nginx goes to the overloaded apache backend,
which gives 200 status content in 60 seconds. What bothers me is the
$request_time value, which shows that it took’s 120second for nginx to
handle the request, and it’s not the sum of memcache and backend
request_time.

For example I’m giving you another log entry where nginx evaluates the
value correctly:

91.180.100.1 www.mydomain.com “23/Oct/2011:21:11:03 +0200”
“10.1.0.41:11211 : 10.1.0.48:82, 10.1.0.46:82” “GET
/?zanpid=1563268107744039936 HTTP/1.1” 301 (404 : 502, 301) UP_RESPONSE
0.001 : 67.387, 35.46
6 request_time 102.854

Here you see that memcache + backends reponse values are equal to the
$request_time value, and this is what I see in my logs by default, the
problematic situation occurs very rarely.

Here is my logformat:
log_format upstream ‘$remote_addr $host “$time_local” “$upstream_addr”
“$request” $status ($upstream_status) UP_RESPONSE
$upstream_response_time request_time $request_time’;

Anybody can explain that behaviour?

Greetz,
Rafal Sawer

Posted at Nginx Forum:

Hello!

On Thu, Oct 27, 2011 at 09:58:01AM -0400, rsawer wrote:

“10.1.0.41:11211 : 10.1.0.48:90” "GET /images/footer-simple.gif
For example I’m giving you another log entry where nginx evaluates the
problematic situation occurs very rarely.

Here is my logformat:
log_format upstream ‘$remote_addr $host “$time_local” “$upstream_addr”
“$request” $status ($upstream_status) UP_RESPONSE
$upstream_response_time request_time $request_time’;

Anybody can explain that behaviour?

The $request_time variable counts full request lifetime, including
reading request from client and sending response to client.

The 120.004 in log entry which bothers you may indicate that
client wasn’t reading response fast enough (or just gave up
waiting and silently gone) and response was actually terminated
due to send_timeout (which defaults to 60s).

Maxim D.

Hi,
thanks Maxim for quick answer, I can always count on you :slight_smile: This could
be the send_timeout, but that would be a little bit odd, because there
were lots of client requests with this kind of issue and the server
didn’t have any load at that time. I’ll will monitor this situation, and
let you know if I’ll get some more info.

Best regards,
Rafał Sawer

Posted at Nginx Forum: