Add variables to hold processing times for modsecurity phases #278

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Open

awmackowiak wants to merge 14 commits into owasp-modsecurity:master

from awmackowiak:master

Open

Add variables to hold processing times for modsecurity phases #278

awmackowiak wants to merge 14 commits into owasp-modsecurity:master from awmackowiak:master

Conversation

awmackowiak

Copy link

@awmackowiak awmackowiak commented Mar 24, 2022 •

edited

Loading

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;

awmackowiak added 3 commits

March 24, 2022 13:36

@awmackowiak


 Add variables to hold processing times for modsecurity phases

e695492

@awmackowiak


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

@awmackowiak


 Merge pull request #1 from awmackowiak/am-logging

75cf7a4

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

liudongmiao

liudongmiao reviewed

Apr 13, 2022

View reviewed changes

src/ngx_http_modsecurity_header_filter.c Outdated Show resolved Hide resolved

src/ngx_http_modsecurity_rewrite.c Outdated Show resolved Hide resolved

src/ngx_http_modsecurity_rewrite.c Outdated

@@ -51,6 +51,9 @@ ngx_http_modsecurity_rewrite_handler(ngx_http_request_t *r)

if (ctx == NULL)

{

int ret = 0;

struct timeval start_tv;

ngx_gettimeofday(&start_tv);

Copy link

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or ngx_current_msec.

Copy link

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sorry, ngx_current_msec is cached. just use ngx_gettimeofday

Copy link

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@liudongmiao

Copy link

liudongmiao commented Apr 13, 2022 •

edited

Loading

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

Copy link

liudongmiao commented Apr 13, 2022

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

smigacz

smigacz approved these changes

Apr 13, 2022

View reviewed changes

@zimmerle

Copy link

Contributor

zimmerle commented Apr 13, 2022

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 -
image

Alternatively you can the have the function level chart -

image

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

Copy link

liudongmiao commented Apr 13, 2022

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

liudongmiao

liudongmiao suggested changes

Apr 15, 2022

View reviewed changes

src/ngx_http_modsecurity_module.c Outdated

ngx_http_modsecurity_logging_phase_time, 0,

NGX_HTTP_VAR_NOCACHEABLE, 0 },

ngx_http_null_variable

Copy link

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link

Author

@awmackowiak awmackowiak May 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes. I change it for old style.

src/ngx_http_modsecurity_module.c Outdated

{ ngx_string("modsecurity_logging_phase_time"), NULL,

ngx_http_modsecurity_logging_phase_time, 0,

NGX_HTTP_VAR_NOCACHEABLE, 0 },

Copy link

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

add NGX_HTTP_VAR_NOHASH?

Copy link

Author

@awmackowiak awmackowiak May 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes you are right. I added it.

src/ngx_http_modsecurity_module.c Outdated

NGX_HTTP_VAR_NOCACHEABLE, 0 },

{ ngx_string("modsecurity_logging_phase_time"), NULL,

ngx_http_modsecurity_logging_phase_time, 0,

Copy link

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link

Author

@awmackowiak awmackowiak May 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link

@liudongmiao liudongmiao May 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

src/ngx_http_modsecurity_pre_access.c Outdated

@@ -209,7 +212,11 @@ ngx_http_modsecurity_pre_access_handler(ngx_http_request_t *r)

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

old_pool = ngx_http_modsecurity_pcre_malloc_init(r->pool);

Copy link

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

remove blank line

awmackowiak and others added 11 commits

May 16, 2022 13:59

@awmackowiak


 Fixes after review

26ac576

@awmackowiak


 Fixes after review

481e463

@awmackowiak


 Fixes after review

811d9a0


 Fixes after review

f7cff06

@awmackowiak


 Fixes after review

55b41d0

@awmackowiak


 Fixes after review

38ec2e3

@awmackowiak


 Fixes after review

6ec6bbb

@awmackowiak


 Fixes after review

aeb5307

@awmackowiak


 Fixes after review

bb939a1

@awmackowiak


 Fixes after review

d386de9

@awmackowiak


 Merge pull request #2 from awmackowiak/am-logging

7aa12d0

Fix after review

@awmackowiak

Copy link

Author

awmackowiak commented May 20, 2022

@liudongmiao I made fixes as you suggests.

@ziollek

Copy link

ziollek commented Apr 1, 2023

@liudongmiao could you review it again?

@liudongmiao

Copy link

liudongmiao commented Apr 3, 2023

@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

Copy link

ziollek commented Apr 3, 2023 •

edited

Loading

@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

Copy link

liudongmiao commented Apr 7, 2023

@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

Copy link

ziollek commented Nov 21, 2023 •

edited

Loading

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 SonarQubeCloud

Copy link

sonarqubecloud bot commented Apr 12, 2024

Quality Gate Passed 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

Labels

None yet

5 participants

@awmackowiak @liudongmiao @zimmerle @ziollek @smigacz

Add variables to hold processing times for modsecurity phases #278

Are you sure you want to change the base?

Add variables to hold processing times for modsecurity phases #278

Uh oh!

Conversation

@awmackowiak 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!

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao Apr 13, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao Apr 13, 2022

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!

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

Uh oh!

@awmackowiak awmackowiak May 16, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

Uh oh!

@awmackowiak awmackowiak May 16, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao Apr 15, 2022

Choose a reason for hiding this comment

Uh oh!

@awmackowiak awmackowiak May 16, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao May 16, 2022

Choose a reason for hiding this comment

Uh oh!

@liudongmiao liudongmiao Apr 15, 2022

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 Quality Gate passed

Uh oh!

Uh oh!

@awmackowiak 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