diff --git a/README.md b/README.md index 2026d53..c83090d 100644 --- a/README.md +++ b/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 diff --git a/src/ngx_http_modsecurity_body_filter.c b/src/ngx_http_modsecurity_body_filter.c index 725f986..04a2b4c 100644 --- a/src/ngx_http_modsecurity_body_filter.c +++ b/src/ngx_http_modsecurity_body_filter.c @@ -156,6 +156,8 @@ 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); @@ -163,6 +165,7 @@ ngx_http_modsecurity_body_filter(ngx_http_request_t *r, ngx_chain_t *in) /* 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; diff --git a/src/ngx_http_modsecurity_common.h b/src/ngx_http_modsecurity_common.h index 60218c4..8282606 100644 --- a/src/ngx_http_modsecurity_common.h +++ b/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_ */ diff --git a/src/ngx_http_modsecurity_header_filter.c b/src/ngx_http_modsecurity_header_filter.c index c36be19..69b64fe 100644 --- a/src/ngx_http_modsecurity_header_filter.c +++ b/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); diff --git a/src/ngx_http_modsecurity_log.c b/src/ngx_http_modsecurity_log.c index d713a65..2b1f363 100644 --- a/src/ngx_http_modsecurity_log.c +++ b/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; } diff --git a/src/ngx_http_modsecurity_module.c b/src/ngx_http_modsecurity_module.c index b6f33f5..993c537 100644 --- a/src/ngx_http_modsecurity_module.c +++ b/src/ngx_http_modsecurity_module.c @@ -25,6 +25,7 @@ #include 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); @@ -32,6 +33,10 @@ static char *ngx_http_modsecurity_merge_conf(ngx_conf_t *cf, void *parent, void 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, ¤t_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: */ diff --git a/src/ngx_http_modsecurity_pre_access.c b/src/ngx_http_modsecurity_pre_access.c index abb7d3e..41370ae 100644 --- a/src/ngx_http_modsecurity_pre_access.c +++ b/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); diff --git a/src/ngx_http_modsecurity_rewrite.c b/src/ngx_http_modsecurity_rewrite.c index f6f8d41..42ed1bd 100644 --- a/src/ngx_http_modsecurity_rewrite.c +++ b/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;