Nginx $ request_time and $ upstream_response_time on Windows

Question

I encounter some kind of weirdness in my access log, which runs Nginx on Windows. I have included $ request_time in my access log as well as $ upstream_response_time (running Django as fcgi upstream). I understand that the log should represent the request time in milliseconds, but the output is as follows:

ip|date|request_time|upstream_response_time xx.xx.xx.xxx|[29/Jan/2013:15:29:57 -0600]|605590388736.19374237|0.141 xx.xx.xx.xxx|[29/Jan/2013:15:30:39 -0600]|670014898176.19374237|0.156 

Any ideas on what this giant number is !?

Here's the full log format (I deleted some columns in the example above)

 log_format main '$remote_addr|$time_local]|$request|$request_time|$upstream_response_time|' '$status|$body_bytes_sent|$http_referer|' '$http_user_agent'; 

Using channel limiters.

Answer 1

So, as you suggest, here comes the answer:

When you make a request to your server ( nginx + upstream ) as GET, then $request_time result with a normal and acceptable value. This is because your upstream server is not involved in it, and even if it does, it does it correctly.

Problems arise when you execute a POST request. According to the nginx doc value, the value of the $request_time variable (available only during logging) will be calculated when all data has been sent and the connection has been closed (by all upstream and proxy servers). And only then the information is added to the journal.

So how to check if everything is correct? First, make a GET request to your server and view the log file. Note how long it takes to end the call and add the log information to the file - this should be a real value. Then do a POST request to your server and view the log file again. Here you will probably see that the magazine does not come at all or after a very long period.

What does it mean? Check your nginx conf and your upstream conf, because somewhere there might be a place where the connection is not closed and just hang in the air. These connections can be resumed after the time of your OS or an upstream server, but in the end it can cause some problems besides just the weird value of $request_time .