Add variables to hold processing times for modsecurity phases

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_body_filter.c

@@ -156,13 +156,16 @@ ngx_http_modsecurity_body_filter(ngx_http_request_t *r, ngx_chain_t *in)
 
         if (is_request_processed) {
             ngx_pool_t *old_pool;
+            struct timespec start_tv;
+            (void) clock_gettime(CLOCK_MONOTONIC, &start_tv);
 
             old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);
             msc_process_response_body(ctx->modsec_transaction);
             ngx_http_modsecurity_pcre_malloc_done(old_pool);
 
 /* XXX: I don't get how body from modsec being transferred to nginx's buffer.  If so - after adjusting of nginx's
    XXX: body we can proceed to adjust body size (content-length).  see xslt_body_filter() for example */
+            ctx->resp_body_phase_time = ngx_http_modsecurity_compute_processing_time(start_tv);
             ret = ngx_http_modsecurity_process_intervention(ctx->modsec_transaction, r, 0);
             if (ret > 0) {
                 return ret;

src/ngx_http_modsecurity_common.h

@@ -99,6 +99,11 @@ typedef struct {
     unsigned processed:1;
     unsigned logged:1;
     unsigned intervention_triggered:1;
+    ngx_msec_int_t req_headers_phase_time;
+    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;
 
 
@@ -164,5 +169,6 @@ ngx_int_t ngx_http_modsecurity_pre_access_handler(ngx_http_request_t *r);
 /* ngx_http_modsecurity_rewrite.c */
 ngx_int_t ngx_http_modsecurity_rewrite_handler(ngx_http_request_t *r);
 
+ngx_msec_int_t ngx_http_modsecurity_compute_processing_time(struct timespec tv);
 
 #endif /* _NGX_HTTP_MODSECURITY_COMMON_H_INCLUDED_ */

src/ngx_http_modsecurity_header_filter.c

@@ -446,6 +446,9 @@ ngx_http_modsecurity_header_filter(ngx_http_request_t *r)
         return ngx_http_next_header_filter(r);
     }
 
+    struct timespec start_tv;
+    (void) clock_gettime(CLOCK_MONOTONIC, &start_tv);
+
     /*
      * Lets ask nginx to keep the response body in memory
      *
@@ -526,6 +529,7 @@ ngx_http_modsecurity_header_filter(ngx_http_request_t *r)
     old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);
     msc_process_response_headers(ctx->modsec_transaction, status, http_response_ver);
     ngx_http_modsecurity_pcre_malloc_done(old_pool);
+    ctx->resp_headers_phase_time = ngx_http_modsecurity_compute_processing_time(start_tv);
     ret = ngx_http_modsecurity_process_intervention(ctx->modsec_transaction, r, 0);
     if (r->error_page) {
         return ngx_http_next_header_filter(r);

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 timespec start_tv;
+    (void) clock_gettime(CLOCK_MONOTONIC, &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

@@ -25,13 +25,18 @@
 #include <ngx_http.h>
 
 static ngx_int_t ngx_http_modsecurity_init(ngx_conf_t *cf);
+static ngx_int_t ngx_http_modsecurity_add_variables(ngx_conf_t *cf);
 static void *ngx_http_modsecurity_create_main_conf(ngx_conf_t *cf);
 static char *ngx_http_modsecurity_init_main_conf(ngx_conf_t *cf, void *conf);
 static void *ngx_http_modsecurity_create_conf(ngx_conf_t *cf);
 static char *ngx_http_modsecurity_merge_conf(ngx_conf_t *cf, void *parent, void *child);
 static void ngx_http_modsecurity_cleanup_instance(void *data);
 static void ngx_http_modsecurity_cleanup_rules(void *data);
 
+static ngx_int_t ngx_http_modsecurity_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);
 
 /*
  * PCRE malloc/free workaround, based on
@@ -268,6 +273,12 @@ ngx_http_modsecurity_create_ctx(ngx_http_request_t *r)
         return NULL;
     }
 
+    ctx->req_headers_phase_time = -1;
+    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);
 
@@ -490,7 +501,7 @@ static ngx_command_t ngx_http_modsecurity_commands[] =  {
 
 
 static ngx_http_module_t ngx_http_modsecurity_ctx = {
-    NULL,                                  /* preconfiguration */
+    ngx_http_modsecurity_add_variables,    /* preconfiguration */
     ngx_http_modsecurity_init,             /* postconfiguration */
 
     ngx_http_modsecurity_create_main_conf, /* create main configuration */
@@ -520,6 +531,31 @@ ngx_module_t ngx_http_modsecurity_module = {
 };
 
 
+static ngx_http_variable_t  ngx_http_modsecurity_vars[] = {
+    { ngx_string("modsecurity_req_headers_phase_time"), NULL,
+      ngx_http_modsecurity_phase_time, 0,
+      NGX_HTTP_VAR_NOCACHEABLE|NGX_HTTP_VAR_NOHASH, 0 },
+
+    { ngx_string("modsecurity_req_body_phase_time"), NULL,
+      ngx_http_modsecurity_phase_time, 1,
+      NGX_HTTP_VAR_NOCACHEABLE|NGX_HTTP_VAR_NOHASH, 0 },
+
+    { ngx_string("modsecurity_resp_headers_phase_time"), NULL,
+      ngx_http_modsecurity_phase_time, 2,
+      NGX_HTTP_VAR_NOCACHEABLE|NGX_HTTP_VAR_NOHASH, 0 },
+
+    { ngx_string("modsecurity_resp_body_phase_time"), NULL,
+      ngx_http_modsecurity_phase_time, 3,
+      NGX_HTTP_VAR_NOCACHEABLE|NGX_HTTP_VAR_NOHASH, 0 },
+
+    { ngx_string("modsecurity_logging_phase_time"), NULL,
+      ngx_http_modsecurity_phase_time, 4,
+      NGX_HTTP_VAR_NOCACHEABLE|NGX_HTTP_VAR_NOHASH, 0 },
+
+    { ngx_null_string, NULL, NULL, 0, 0, 0 }
+};
+
+
 static ngx_int_t
 ngx_http_modsecurity_init(ngx_conf_t *cf)
 {
@@ -596,6 +632,23 @@ ngx_http_modsecurity_init(ngx_conf_t *cf)
     return NGX_OK;
 }
 
+static ngx_int_t
+ngx_http_modsecurity_add_variables(ngx_conf_t *cf) {
+    ngx_http_variable_t  *var, *v;
+
+    for (v = ngx_http_modsecurity_vars; v->name.len; v++) {
+        var = ngx_http_add_variable(cf, &v->name, v->flags);
+        if (var == NULL) {
+            return NGX_ERROR;
+        }
+
+        var->get_handler = v->get_handler;
+        var->data = v->data;
+    }
+
+    return NGX_OK;
+};
+
 
 static void *
 ngx_http_modsecurity_create_main_conf(ngx_conf_t *cf)
@@ -788,4 +841,65 @@ ngx_http_modsecurity_cleanup_rules(void *data)
 }
 
 
+static ngx_int_t
+ngx_http_modsecurity_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;
+    }
+
+    switch(data) {
+        case 0:
+            return ngx_http_modsecurity_time_variable(r, v, data, ctx->req_headers_phase_time);
+        case 1:
+            return ngx_http_modsecurity_time_variable(r, v, data, ctx->req_body_phase_time);
+        case 2:
+            return ngx_http_modsecurity_time_variable(r, v, data, ctx->resp_headers_phase_time);
+        case 3:
+            return ngx_http_modsecurity_time_variable(r, v, data, ctx->resp_body_phase_time);
+        case 4:
+            return ngx_http_modsecurity_time_variable(r, v, data, ctx->logging_phase_time);
+        default:
+            return -1;
+    }
+}
+
+
+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)
+{
+    u_char  *p;
+
+    p = ngx_pnalloc(r->pool, NGX_TIME_T_LEN + 7);
+    if (p == NULL) {
+        return NGX_ERROR;
+    }
+
+    if(usec == -1) {
+        v->len = ngx_sprintf(p, "-") - p;
+    } else  {
+        v->len = ngx_sprintf(p, "%T.%06M", (time_t) usec / 1000000, usec % 1000000) - p;
+    }
+
+    v->valid = 1;
+    v->no_cacheable = 0;
+    v->not_found = 0;
+    v->data = p;
+
+    return NGX_OK;
+}
+
+
+ngx_msec_int_t
+ngx_http_modsecurity_compute_processing_time(struct timespec tv) {
+    struct timespec current_tv;
+    (void) clock_gettime(CLOCK_MONOTONIC, &current_tv);
+    return (ngx_msec_int_t) ((current_tv.tv_sec - tv.tv_sec) * 1000000 + (current_tv.tv_nsec - tv.tv_nsec) / 1000);
+};
+
 /* vi:set ft=c ts=4 sw=4 et fdm=marker: */

src/ngx_http_modsecurity_pre_access.c

@@ -140,6 +140,9 @@ ngx_http_modsecurity_pre_access_handler(ngx_http_request_t *r)
         int ret = 0;
         int already_inspected = 0;
 
+        struct timespec start_tv;
+        (void) clock_gettime(CLOCK_MONOTONIC, &start_tv);
+
         dd("request body is ready to be processed");
 
         r->write_event_handler = ngx_http_core_run_phases;
@@ -210,6 +213,7 @@ ngx_http_modsecurity_pre_access_handler(ngx_http_request_t *r)
 
         old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);
         msc_process_request_body(ctx->modsec_transaction);
+        ctx->req_body_phase_time = ngx_http_modsecurity_compute_processing_time(start_tv);
         ngx_http_modsecurity_pcre_malloc_done(old_pool);
 
         ret = ngx_http_modsecurity_process_intervention(ctx->modsec_transaction, r, 0);

src/ngx_http_modsecurity_rewrite.c

@@ -51,6 +51,8 @@ ngx_http_modsecurity_rewrite_handler(ngx_http_request_t *r)
     if (ctx == NULL)
     {
         int ret = 0;
+        struct timespec start_tv;
+        (void) clock_gettime(CLOCK_MONOTONIC, &start_tv);
 
         ngx_connection_t *connection = r->connection;
         /**
@@ -205,6 +207,7 @@ ngx_http_modsecurity_rewrite_handler(ngx_http_request_t *r)
         msc_process_request_headers(ctx->modsec_transaction);
         ngx_http_modsecurity_pcre_malloc_done(old_pool);
         dd("Processing intervention with the request headers information filled in");
+        ctx->req_headers_phase_time = ngx_http_modsecurity_compute_processing_time(start_tv);
         ret = ngx_http_modsecurity_process_intervention(ctx->modsec_transaction, r, 1);
         if (r->error_page) {
             return NGX_DECLINED;