Add variables to hold processing times for modsecurity phases

[awmackowiak]

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:

    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;

[liudongmiao]

For waf performance, I'd like to implement as this (in nginx module):

1. when modsecurity context / transaction is created, record it as modsec_request_start_time
2. when ngx_http_modsecurity_process_intervention is finished, update it as modsec_request_end_time
3. Calc modsec_request_end_time - modsec_start_time as modsec_request_time.

For response, it's hard to implement, as there may be multi upstream (refer upstream_response_time in upstream module: http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_response_time). However, I have commented out the response headers / body handlers, and have no modsec rules in phase 3 / 4.

For modsec rules performance, I'd like to implement it in modsecurity.

[liudongmiao]

@awmackowiak Could you help to review https://github.com/SpiderLabs/ModSecurity-nginx/pull/273 and https://github.com/SpiderLabs/ModSecurity-nginx/pull/277?

[zimmerle]

Have you guys tried the performance instrumentation? The perf. instrumentation seems to have all the information that you guys are trying to collect.

https://github.com/SpiderLabs/ModSecurity-nginx/blob/master/ngx-modsec.stp

That is the output -

Alternatively you can the have the function level chart -

That is an interactive SVG, like this one - https://www.brendangregg.com/FlameGraphs/cpu-mysql-updated.svg

Also, you can compare ModSecurity execution times outside nginx, by using the command line utilities -

https://github.com/SpiderLabs/ModSecurity/tree/v3/master/test

All that without having to patch a single line from ModSecurity.

Patching ModSecurity to support some sort of performance indicators was discussed here - https://github.com/SpiderLabs/ModSecurity/issues/1011

[liudongmiao]

@zimmerle We'd like to record waf time in log...just as request_time and upstream_response_time...

[awmackowiak]

@liudongmiao I made fixes as you suggests.

[ziollek]

@liudongmiao could you review it again?

[liudongmiao]

@ziollek These codes are ok.

However, we use another solution, calc the total modsec time, named it as "msc_request_time" and "msc_engine_time".

• msc_request_time: the time cost between the beginning and complete
• msc_engine_time: the time cost by modsecurity engine, sum all steps And in production, msc_request_time is same as msc_engine_time for GET request, for large POST, msc_request_time is greater than msc_engine_time.

[ziollek]

@liudongmiao thanks for reply. Could you point out where these variables are described? Are they exposed as a nginx variables?

I would like to give you some insights what need states behind this change. We implemented those changes because we encountered a hard to diagnose performance issue (connected with this PR: https://github.com/SpiderLabs/ModSecurity/issues/2601). In order to increase WAF observability we want to measure libmodsecurity overhead. The simplest (from our point of view) solution seems to be an adding such overhead of each request to nginx log (and later build appropriate metrics based on nginx log).

[liudongmiao]

@ziollek Yes, we have the same problem. We export it to nginx variables, and update the nginx log format. In our production, we add three variables: msc_request_time / msc_engine_time / msc_rules_messages. I have explained the msc_request_time and msc_engine_time.

In our production, the average msc_engine_time is about 1ms, and 95% is less than 5ms, which is acceptable by our team.

[ziollek]

Have you guys tried the performance instrumentation? The perf. instrumentation seems to have all the information that you guys are trying to collect.

https://github.com/SpiderLabs/ModSecurity-nginx/blob/master/ngx-modsec.stp

@zimmerle Thanks for pointing out this tool, I was not aware of that. Lately, I had some spare time and I tried to profile using it, and I have some thoughts about it. First of all, it is really cumbersome using systemtap in a containerized environment (and currently it is quite common that such workload is run for example in k8s). Secondly, the script provided within the plugin is outdated, it tries tracking calls that no longer exist in libmodsecurity.so

And finally, I think that there is some misunderstanding of the purpose of such changes. We do not want to provide another way of profiling ModSecurity. We wanted to increase observability. Internally in our company, we have defined metrics based on times reported by introduced new variables. Our WAF ecosystem based partially on ModSecurity is complex and configuration is changed very often. Thanks to measuring the overhead of each component by such kinds of metrics we have insights that allow very fast tracing down the root cause of performance problems.

[sonarcloud[bot]]

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
No data about Coverage
No data about Duplication

See analysis details on SonarCloud