Menu
I'm encountering some weirdness in my access log running Nginx on Windows. I've included $request_time in my access log as well as $upstream_response_time (running Django as fcgi upstream). It's my understanding that the log should represent request time in milleseconds, but it's output looks like this:
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 what the heck that gigantic number is!?
Here's the full log format (I removed a few columns in teh above example)
log_format main '$remote_addr|$time_local]|$request|$request_time|$upstream_response_time|'
'$status|$body_bytes_sent|$http_referer|'
'$http_user_agent';
Using pipe delimiters.
721
$request_time – Full request time, starting when NGINX reads the first byte from the client and ending when NGINX sends the last byte of the response body. Which means by "last byte sent to the client" that it also includes the client response time.
By default, the access log is located at /var/log/nginx/access. log , and the information is written to the log in the predefined combined format. You can override the default settings and change the format of logged messages by editing the NGINX configuration file ( /etc/nginx/nginx. conf by default).
The syntax for configuring a log format is: log_format format_name 'set_of_variables_to_define_format'; and the syntax for configuring access log is: access_log /path/to/log_file format_name; #simplest form OR access_log /path/to/log_file [format [buffer=size] [gzip[=level]] [flush=time] [if=condition]];
If you wish to turn off the Nginx error logs completely, you need to change the line to : error_log /dev/null crit; This will completely turn off the Nginx error logs on your server.
So as you suggest here comes the answer:
When you make request to your server (nginx + upstream) as GET then $request_time result with normal and acceptable value. That happens because your upstream server doesn't take part in it and even if it does it makes it properly.
Problems start when you are doing POST request. According to nginx doc value of $request_time variable (available only at logging) will be compute when all data have been send and connection have been closed (by all upstreams and proxy also). And only then info is appended to log.
So how to check if everything is correct? First do a GET request to your server and watch log file. Notice how much time it really takes to finish the call and add log info into file - it should be real value. Next do a POST request to your server and watch log file again. Here, probably, you will see that log isn't coming at all or after very long period.
What it means? Check your nginx conf and your upstream conf because somewhere could be a place where connection isn't closed and just hang in the air. Those connection could be renew after time by your OS or upstream server but after all it could cause some problems other than just strange $request_time value.
136
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With
