# Strange log entries (upstream time/request\_time) **URL:** \ **Category:** NGINX\ **Created:** [October 27, 2011, 3:58pm UTC](https://www.ruby-forum.com/t/strange-log-entries-upstream-time-request-time/213243 "2011-10-27T15:58:42Z")\ **Posts on this page:** 3\ **Page:** 1
**Author:** ![luislavena](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/l/0ea827/32.png) [@luislavena](https://www.ruby-forum.com/u/luislavena)\ **Post date:** [October 27, 2011, 3:58pm UTC](https://www.ruby-forum.com/t/strange-log-entries-upstream-time-request-time/213243/1 "2011-10-27T15:58:42Z")
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](http://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](http://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: > **[Strange log entries (upstream time/request\_time)](https://forum.nginx.org/read.php?2,217430,217430#msg-217430)** > > 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... ---
**Author:** ![rsawer](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/r/dc4da7/32.png) [@rsawer](https://www.ruby-forum.com/u/rsawer)\ **Post date:** [October 27, 2011, 4:33pm UTC](https://www.ruby-forum.com/t/strange-log-entries-upstream-time-request-time/213243/2 "2011-10-27T16:33:20Z")
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. ---
**Author:** ![rsawer](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/r/dc4da7/32.png) [@rsawer](https://www.ruby-forum.com/u/rsawer)\ **Post date:** [October 28, 2011, 2:39pm UTC](https://www.ruby-forum.com/t/strange-log-entries-upstream-time-request-time/213243/3 "2011-10-28T14:39:35Z")
Hi, thanks Maxim for quick answer, I can always count on you 🙂 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: > **[Re: Strange log entries (upstream time/request\_time)](https://forum.nginx.org/read.php?2,217430,217463#msg-217463)** > > 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...