Add variables to hold processing times for modsecurity phases by awmackowiak · Pull Request #278 · owasp-modsecurity/ModSecurity-nginx

awmackowiak · 2022-03-24T12:42:15Z

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;

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

src/ngx_http_modsecurity_header_filter.c

src/ngx_http_modsecurity_rewrite.c

liudongmiao · 2022-04-13T05:58:16Z

src/ngx_http_modsecurity_rewrite.c

        int ret = 0;
+        struct timeval start_tv;
+
+        ngx_gettimeofday(&start_tv);


I suggest use ngx_timeofday like request_time or upstream_xxx_time in upstream module.

Or ngx_current_msec.

sorry, ngx_current_msec is cached. just use ngx_gettimeofday

I'd like to use clock_gettime with CLOCK_MONOTONIC for ns.

liudongmiao · 2022-04-13T06:37:08Z

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

when modsecurity context / transaction is created, record it as modsec_request_start_time
when ngx_http_modsecurity_process_intervention is finished, update it as modsec_request_end_time
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 · 2022-04-13T06:40:38Z

@awmackowiak Could you help to review #273 and #277?

zimmerle · 2022-04-13T13:50:40Z

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 - owasp-modsecurity/ModSecurity#1011

liudongmiao · 2022-04-13T15:23:37Z

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

liudongmiao · 2022-04-15T01:55:54Z

src/ngx_http_modsecurity_module.c

+      ngx_http_modsecurity_logging_phase_time, 0,
+      NGX_HTTP_VAR_NOCACHEABLE, 0 },
+
+      ngx_http_null_variable


ngx_http_null_variable is introduced in 1.13.4, expand it to support old nginx. nginx/nginx@b992f72

Yes. I change it for old style.

liudongmiao · 2022-04-15T01:56:42Z

src/ngx_http_modsecurity_module.c

+
+    { ngx_string("modsecurity_logging_phase_time"), NULL,
+      ngx_http_modsecurity_logging_phase_time, 0,
+      NGX_HTTP_VAR_NOCACHEABLE, 0 },


add NGX_HTTP_VAR_NOHASH?

Yes you are right. I added it.

liudongmiao · 2022-04-15T01:58:09Z

src/ngx_http_modsecurity_module.c

+      NGX_HTTP_VAR_NOCACHEABLE, 0 },
+
+    { ngx_string("modsecurity_logging_phase_time"), NULL,
+      ngx_http_modsecurity_logging_phase_time, 0,


use a same function with different argument, like 0, 1, 2, ...

Can you provide an example what are you mean for that?
I didn't find example for variables with indexed arguments.

Refer https://github.com/nginx/nginx/blob/release-1.21.6/src/http/ngx_http_upstream.c#L391-L401
Same function ngx_http_upstream_response_time_variable for 3 variables.

liudongmiao · 2022-04-15T01:59:12Z

src/ngx_http_modsecurity_pre_access.c

 /* XXX: once more -- is body can be modified ?  content-length need to be adjusted ? */

        old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);
+


remove blank line

Fix after review

awmackowiak · 2022-05-20T06:16:52Z

@liudongmiao I made fixes as you suggests.

ziollek · 2023-04-01T07:40:16Z

@liudongmiao could you review it again?

liudongmiao · 2023-04-03T03:37:05Z

@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 · 2023-04-03T18:38:32Z

@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: owasp-modsecurity/ModSecurity#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 · 2023-04-07T06:26:33Z

@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 · 2023-11-21T19:53:02Z

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.

sonarqubecloud · 2024-04-12T13:06:14Z

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

awmackowiak added 3 commits March 24, 2022 13:36

Add variables to hold processing times for modsecurity phases

e695492

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

8052510

Merge pull request #1 from awmackowiak/am-logging

75cf7a4

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

liudongmiao reviewed Apr 13, 2022

View reviewed changes

smigacz approved these changes Apr 13, 2022

View reviewed changes

liudongmiao suggested changes Apr 15, 2022

View reviewed changes

awmackowiak and others added 11 commits May 16, 2022 13:59

Fixes after review

26ac576

Fixes after review

481e463

Fixes after review

811d9a0

Fixes after review

f7cff06

Fixes after review

55b41d0

Fixes after review

38ec2e3

Fixes after review

6ec6bbb

Fixes after review

aeb5307

Fixes after review

bb939a1

Fixes after review

d386de9

Merge pull request #2 from awmackowiak/am-logging

7aa12d0

Fix after review

		/* XXX: once more -- is body can be modified ? content-length need to be adjusted ? */

		old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);

Conversation

awmackowiak commented Mar 24, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Format Variables

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

liudongmiao commented Apr 13, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

liudongmiao commented Apr 13, 2022

Uh oh!

zimmerle commented Apr 13, 2022

Uh oh!

liudongmiao commented Apr 13, 2022

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

awmackowiak commented May 20, 2022

Uh oh!

ziollek commented Apr 1, 2023

Uh oh!

liudongmiao commented Apr 3, 2023

Uh oh!

ziollek commented Apr 3, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

liudongmiao commented Apr 7, 2023

Uh oh!

ziollek commented Nov 21, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sonarqubecloud bot commented Apr 12, 2024

Quality Gate passed

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

awmackowiak commented Mar 24, 2022 •

edited

Loading

liudongmiao commented Apr 13, 2022 •

edited

Loading

ziollek commented Apr 3, 2023 •

edited

Loading

ziollek commented Nov 21, 2023 •

edited

Loading