Blackbox Logs

[Maxim Dounin]

Hello!

On Thu, Jun 17, 2010 at 10:59:27AM -0500, Alan Gutierrez wrote:

> I attempted to get a discussion going on ServerFault.com regarding
> "blackbox" logs and Nginx. It didn't get the response I imagined,
> and I was told to ask here.
> 
> Here is an article about "blackbox" logs in Apache by Chris Josephes
> from 2004.
> 
> http://onlamp.com/pub/a/apache/2004/04/22/blackbox_logs.html
> 
> I've always kept these logs around on my Apache servers and they
> have come in handy. I'm trying to recreate them for Nginx. Here is
> the Apache format.
> 
> LogFormat "%a/%S %X %t \"%r\" %s/%>s %{pid}P/%{tid}P %T/%D %I/%O/%B"
> blackbox
> 
> Here's what Nginx blackbox format would look like, the unmapped
> Apache directives have question marks after their names.
> access_log blackbox '$remote_addr/$remote_port X? [$time_local]
> "$request"'
>                     's?/$status $pid/0 T?/D? I?/$bytes_sent/
> $body_bytes_sent'
> Here's a table of the variables I've been able to map from the Nginx
> documentation.
> %a = $remote_addr - The IP address of the remote client.
> %S = $remote_port - The port of the remote client.
> %X = ? - Keep alive status.

Logging $sent_http_connection should be enough, but due to a bug 
it currently always evaluates to "closed" during request logging.  
Patch below.

> %t = $time_local - The start time of the request.
> %r = $request - The first line of request containing method verb,
> path and protocol.
> %s = ? - Status before any redirections.

There is no such thing in nginx.

> %>s = $status - Status after any redirections.
> %{pid}P = $pid - The process id.
> %{tid}P = N/A - The thread id, which is non-applicable to Nignx.
> %T = ? - The time in seconds to handle the request.
> %D = $request_time - The time in milliseconds to handle the request.
> %I = ? - The count of bytes received including headers.

$request_length

Note that it's *including* headers, while documentation says (in 
russian) something like "length of request body".

> %O = $bytes_sent - The count of bytes sent including headers.
> %B = $body_bytes_sent - The count of bytes sent excluding headers,
> but with a 0 for none instead of '-'.
> So, I'm missing %I bytes received and %X keep alive status. The
> timings are off, but I don't mind.
> Nginx doesn't to milliseconds like Apache, but rather seconds with
> millisecond precision. Making the log format exactly like the Apache
> blackbox log format would be a nice exercise, but it is not
> imperative.  If Nginx can do simple adjustments using multiplication
> that would be cool, but I haven't tried it yet, nor have I seen any
> examples of it.

Actually, most important thing to log is $upstream_response_time.  
So it's not a good idea to log something in an "apache compatible" 
format as you are going to log wrong metrics in this case. 

Maxim Dounin

p.s.

diff --git a/src/http/ngx_http_request.c b/src/http/ngx_http_request.c
--- a/src/http/ngx_http_request.c
+++ b/src/http/ngx_http_request.c
@@ -2435,10 +2435,10 @@ ngx_http_set_keepalive(ngx_http_request_
         }
     }

+    ngx_http_free_request(r, 0);
+
     r->keepalive = 0;

-    ngx_http_free_request(r, 0);
-
     c->data = hc;

     ngx_add_timer(rev, clcf->keepalive_timeout);