Merge pull request #1 from awmackowiak/am-logging

Add variable for logging time and add examples how to use it to README

Author: awmackowiak

README.md

@@ -176,6 +176,27 @@ using the same unique identificator.
 
 String can contain variables.
 
+# Format Variables
+ModSecurity-nginx provide times variables for particular phases that you can uses in nginx *log_format*:
+
+    *$modsecurity_req_headers_phase_time*
+        request headers processing time in seconds with a microseconds resolution; time elapsed for processing headers in first phase by ModSecurity
+    *$modsecurity_req_body_phase_time*
+        request body processing time in seconds with a microseconds resolution; time elapsed for processing request body in second phase by ModSecurity
+    *$modsecurity_resp_headers_phase_time*
+        resposnse headers processing time in seconds with a microseconds resolution; time elapsed for processing response headers in third phase by ModSecurity
+    *$modsecurity_resp_body_phase_time*
+        response body processing time in seconds with a microseconds resolution; time elapsed for processing response body in fourth phase by ModSecurity
+    *$modsecurity_logging_phase_time*
+        logging processing time in seconds with a microseconds resolution; time elapsed for processing logging in fifth phase by ModSecurity
+
+The following example show how to configure custom *log_format* with variables above and use them with custom *access.log*:
+
+```nginx
+    log_format format_modsecurity 'modsecurity_req_headers_phase_time: $modsecurity_req_headers_phase_time, modsecurity_req_body_phase_time: $modsecurity_req_body_phase_time, modsecurity_resp_headers_phase_time: $modsecurity_resp_headers_phase_time, modsecurity_resp_body_phase_time: $modsecurity_resp_body_phase_time, modsecurity_logging_phase_time: $modsecurity_logging_phase_time';
+
+    access_log /usr/local/nginx/logs/modsecurity.log format_modsecurity;
+```
 
 # Contributing
 

src/ngx_http_modsecurity_common.h

@@ -103,6 +103,7 @@ typedef struct {
     ngx_msec_int_t req_body_phase_time;
     ngx_msec_int_t resp_headers_phase_time;
     ngx_msec_int_t resp_body_phase_time;
+    ngx_msec_int_t logging_phase_time;
 } ngx_http_modsecurity_ctx_t;
 
 

src/ngx_http_modsecurity_log.c

@@ -71,11 +71,14 @@ ngx_http_modsecurity_log_handler(ngx_http_request_t *r)
         dd("already logged earlier");
         return NGX_OK;
     }
+    struct timeval start_tv;
+    ngx_gettimeofday(&start_tv);
 
     dd("calling msc_process_logging for %p", ctx);
     old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);
     msc_process_logging(ctx->modsec_transaction);
     ngx_http_modsecurity_pcre_malloc_done(old_pool);
+    ctx->logging_phase_time = ngx_http_modsecurity_compute_processing_time(start_tv);
 
     return NGX_OK;
 }

src/ngx_http_modsecurity_module.c

@@ -41,6 +41,8 @@ static ngx_int_t ngx_http_modsecurity_resp_headers_phase_time(ngx_http_request_t
     ngx_http_variable_value_t *v, uintptr_t data);
 static ngx_int_t ngx_http_modsecurity_resp_body_phase_time(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data);
+static ngx_int_t ngx_http_modsecurity_logging_phase_time(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data);
 static ngx_int_t ngx_http_modsecurity_time_variable(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data, ngx_msec_int_t usec);
 
@@ -283,6 +285,7 @@ ngx_http_modsecurity_create_ctx(ngx_http_request_t *r)
     ctx->req_body_phase_time = -1;
     ctx->resp_headers_phase_time = -1;
     ctx->resp_body_phase_time = -1;
+    ctx->logging_phase_time = -1;
 
     mmcf = ngx_http_get_module_main_conf(r, ngx_http_modsecurity_module);
     mcf = ngx_http_get_module_loc_conf(r, ngx_http_modsecurity_module);
@@ -553,6 +556,10 @@ static ngx_http_variable_t  ngx_http_modsecurity_vars[] = {
       ngx_http_modsecurity_resp_body_phase_time, 0,
       NGX_HTTP_VAR_NOCACHEABLE, 0 },
 
+    { ngx_string("modsecurity_logging_phase_time"), NULL,
+      ngx_http_modsecurity_logging_phase_time, 0,
+      NGX_HTTP_VAR_NOCACHEABLE, 0 },
+
       ngx_http_null_variable
 };
 
@@ -897,6 +904,21 @@ ngx_http_modsecurity_resp_body_phase_time(ngx_http_request_t *r,
     return ngx_http_modsecurity_time_variable(r, v, data, ctx->resp_body_phase_time);
 }
 
+
+static ngx_int_t
+ngx_http_modsecurity_logging_phase_time(ngx_http_request_t *r,
+    ngx_http_variable_value_t *v, uintptr_t data)
+{
+    ngx_http_modsecurity_ctx_t *ctx;
+
+    ctx = ngx_http_get_module_ctx(r, ngx_http_modsecurity_module);
+    if (ctx == NULL) {
+        return NGX_ERROR;
+    }
+    return ngx_http_modsecurity_time_variable(r, v, data, ctx->logging_phase_time);
+}
+
+
 static ngx_int_t
 ngx_http_modsecurity_time_variable(ngx_http_request_t *r,
     ngx_http_variable_value_t *v, uintptr_t data, ngx_msec_int_t usec)