[Question]How to best tune audit/debug log so they ONLY are produced when tx's would be blocked by ModSecurity?

[jeremyjpj0916]

One Idea I had was replacing here:
https://github.com/SpiderLabs/ModSecurity-nginx/blob/master/src/ngx_http_modsecurity_log.c#L72

if (ctx->modsec_transaction->intervention()) {
msc_process_logging(ctx->modsec_transaction);
}

This should allow only audit/debug logging to run on transactions that were intervened. This is very close to what I would want I think, but I would lose logs I think if I were running the WAF in non-blocking mode because no interventions occur right? Is there a difference reference I can lock in on here that accomplishes "only log when WAF rules have been violated"?

Note I tried to set relevancy to HTTP 400/403(the statuses that cause blocking by WAF), but problem there is my backend API's my NGINX reverse proxy too can sometimes throw 400/403 and I want to prevent those from being logged.

Also Audit log set to relevant only vs on etc. didn't make a difference either.

[jeremyjpj0916]

Hmm trying that reference gives me a:

#22 71.63 /ModSecurity-nginx/src/ngx_http_modsecurity_log.c:75:31: error: dereferencing pointer to incomplete type 'Transaction' {aka 'struct Transaction_t'}
#22 71.63 if(ctx->modsec_transaction->intervention()) {

during my build. Back to drawing board.

[jeremyjpj0916]

@victorhora @zimmerle @martinhsv

Looking to your guidance here if you have a spare 20 mins, related to this git issue partially as well. Trying to productionalize the v3 ModSecurity WAF w NGINX but I keep coming back to a few main pain points around how I will accomplish getting proper insights in DetectionOnly mode in production to monitor what ModSecurity would have blocked.

My biggest concerns are currently this in the WAF design:

1. How to get logs of the things that would have been blocked much like they do when its in blocking mode when they are blocked, currently in our stdout/stderr we get these logs:

ex:

2020/04/30 21:28:22 [error] 89#0: *2931150 [client 52.200.199.161] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator Ge' with parameter 5' against variable TX:ANOMALY_SCORE' (Value: 5' ) [file "/usr/local/owasp-modsecurity-crs-3.2.0/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "83"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5), [rules: 920170"] [data ""] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "10.131.7.72"] [uri "/api/test/v3.0"] [unique_id "158828210257.626867"] [ref ""], client: 52.xxx.xxx.xxx, server: kong, request: "POST /api/test/v3.0 HTTP/1.1", upstream: "https://10.xxx.xxx.xxx:443/prweb/PRRestService/Service/v3 ", host: "gateway-stage.company.com"

In DetectOnly mode I feel I need something like this to be adequately prepared to handle evaluations in non-blocking mode, right now there are no logs for DetectionOnly mode:

ex:

2020/04/30 21:28:22 [error] 89#0: *2931150 [client 52.200.199.161] ModSecurity: Access would have been denied with code 403 (phase 2) ,but WAF is in DetectionOnly mode. Matched "Operator Ge' with parameter 5' against variable TX:ANOMALY_SCORE' (Value: 5' ) [file "/usr/local/owasp-modsecurity-crs-3.2.0/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "83"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 5), [rules: 920170"] [data ""] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "10.131.7.72"] [uri "/api/test/v3.0"] [unique_id "158828210257.626867"] [ref ""], client: 52.xxx.xxx.xxx, server: kong, request: "POST /api/test/v3.0 HTTP/1.1", upstream: "https://10.xxx.xxx.xxx:443/prweb/PRRestService/Service/v3 ", host: "gateway-stage.company.com"

Note the small change in wording to account for the non-blocking mode as well as the change in error log level (error) to (notice).

Is there a simple snippit I could add either in the connector here or in the https://github.com/SpiderLabs/ModSecurity source to accomplish this when in non-blocking mode? I would be happy to PR it if you think its a simple one liner and could point me where it goes and the snippit to test with?

EDIT - PART 1 SOLVED

2. Audit logs collecting files around what would have met blocking criteria if it were not for DetectionOnly mode? By design you can isolate audit logs to a relevant HTTP Status, which is all fine and dandy when you are in blocking mode cause you can isolate by http status to 400 and 403's to get most the noise background out, but once you are in non-blocking mode there is no http status code to focus on to only log relevant blocked tx's. And audit logging all transactions is not feasible, it would produce too many log files for the small nodes I run handling the traffic, not to mention the performance hit with logs I have no need for on 200 status tx's. Is there a way in the code I attempted in original git issue raised here that I can add either in this connector library or the original source lib https://github.com/SpiderLabs/ModSecurity that will only audit log files when a transaction has had an intervention on? That would give me exactly the behavior I would desire out of a WAF.

I owe a beer to the one that helps me out with these headaches, they are the major last points of issue we have with the WAF solution currently. I suck at C code too 😆 . If this was some Java or Lua I think I could likely handle it myself.

Edit - Observed behavior is that when running in DetectionOnly mode I get no stdout/stderror logs of the event to view in my docker container pod. IF I run audit log mode set to On to grab everything I do see section H exclusively in the audit log files populated with the blocks, so I know modsec has saved the data it could expose more helpfully in multiple places:

Ex:

---StFxOtMz---H--
ModSecurity: Warning. Matched "Operator `Rx' with parameter `(?i)(?:;|\{|\||\|\||&|&&|\n|\r|`)\s*[\(,@\'\"\s]*(?:[\w'\"\./]+/|[\\\\'\"\^]*\w[\\\\'\"\^]*:.*\\\\|[\^\.\w '\"/\\\\]*\\\\)?[\"\^
]*(?:s[\"\^]*(?:y[\"\^]*s[\"\^]*(?:t[\"\^]*e[\"\^]*m[\"\^]*(?:p[\"\^]*r[ (5048 characters omitted)' against variable `XML:/*' (Value: `\x0aselect the decision to be taken\x0a' ) [file "/usr
/local/owasp-modsecurity-crs-3.2.0/rules/REQUEST-932-APPLICATION-ATTACK-RCE.conf"] [line "284"] [id "932115"] [rev ""] [msg "Remote Command Execution: Windows Command Injection"] [data "Matched Data: \x0aselect found within XML:/*: \x0aselect the decision to be taken\x0a"] [severity "2"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-shell"] [tag "platform-windows"] [tag "attack-rce"] [tag "OWASP_CRS"] [tag "OWASP_CRS/WEB_ATTACK/COMMAND_INJECTION"] [tag "WASCTC/WASC-31"] [tag "OWASP_TOP_10/A1"] [tag "PCI/6.5.2"] [
hostname "10.128.101.94"] [uri "/F5/status/derp"] [unique_id "158831492745.411098"] [ref "o0,7"]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `(?i:(?:^[\W\d]+\s*?(?:alter\s*(?:a(?:(?:pplication\s*rol|ggregat)e|s(?:ymmetric\s*ke|sembl)y|u(?:thorization|dit)|vailability\s*group)|c(?:r(?:yptographic\s*provider|edential)|o(?:l(?:latio|um)|nversi (1029 characters omitted)' against variable `XML:/*' (Value: `\x0aselect the decision to be taken\x0a' ) [file "/usr/local/owasp-modsecurity-crs-3.2.0/rules/REQUEST-942-APPLICATION-ATTACK-SQLI.conf"] [line "464"] [id "942360"] [rev ""] [msg "Detects concatenated basic SQL injection and SQLLFI attempts"][data "Matched Data: \x0aselect found within XML:/*: \x0aselect the decision to be taken\x0a"] [severity "2"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-sqli"] [tag "OWASP_CRS"] [tag "OWASP_CRS/WEB_ATTACK/SQL_INJECTION"] [tag "WASCTC/WASC-19"] [tag "OWASP_TOP_10/A1"] [tag "OWASP_AppSensor/CIE1"] [tag "PCI/6.5.2"] [hostname "10.128.101.94"] [uri "/F5/status/derp"] [unique_id "158831492745.411098"] [ref "o0,7t:urlDecodeUni"]
ModSecurity: Warning. Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `10' ) [file "/usr/local/owasp-modsecurity-crs-3.2.0/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "83"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 10), [rules: 932115"] [data ""] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "10.128.101.94"] [uri "/F5/status/derp"] [unique_id "158831492745.411098"] [ref ""]

Looks like for these that don't get exposed to stdout/err it adds ModSecurity: Warning. to the front of the likewise blocking message, which is good enough for me also for stdout/err output anyways under [notice] NGX level.

cc @airween I know I talked to you on slack about this from the logging side since you know C much better than me and you had hacked together some C files that let you do some of the audit logging to be specifically only blocked tx's with an extra rule id made around it as well. Will re-review our convo too to see if some of the custom src you wrote up makes sense as a PR.

[jeremyjpj0916]

Trying to follow the code around and finding where messages are generated is here:

https://github.com/SpiderLabs/ModSecurity/blob/v3/master/src/rule_message.cc#L66

Seems then this is the meat of what decides what goes just to a copy saved for audit logging or also to server logging if its an error potentially:
https://github.com/SpiderLabs/ModSecurity/blob/v3/master/src/rule_with_actions.cc

Althought I am a bit hazy trying to follow the point of if(lastlog) {..} else {...} bit. But otherwise seems like if I wanted the DetectionOnly(which just produces the warning message) to also go to the server error log logic of nxinx or apache. Then I could remove the if() checks and let:

                /* error */
                if (!ruleMessage->m_isDisruptive) {
                    trans->serverLog(ruleMessage);
                }

Becomes:

trans->serverLog(ruleMessage); //Force DetectionOnly warning message into server error logs too. 

Within this file... but idk if I should just do it at the lastlog bit or every single spot I see this... code is hard to follow for a newb unfamiliar to the project xD .

I also see a serverLog call here, but no conditionals or rule messages around here so I don't view this as a place to modify it:
https://github.com/SpiderLabs/ModSecurity/blob/v3/master/src/transaction.cc#L1815

[jeremyjpj0916]

Hmm did try editing this method to be like this, but my NGINX logs did not print the warning statements when in DetectionOnly mode :/ :

void RuleWithActions::performLogging(Transaction *trans,
    std::shared_ptr<RuleMessage> ruleMessage,
    bool lastLog,
    bool chainedParentNull) {

    /* last rule in the chain. */
    bool isItToBeLogged = ruleMessage->m_saveMessage;

    /**
    *
    * RuleMessage is stacked allocated for the rule execution,
    * anything beyond this may lead to invalid pointer access.
    *
    * In case of a warning, o set of messages is saved to be read
    * at audit log generation. Therefore demands a copy here.
    *
    * FIXME: Study an way to avoid the copy.
    *
    **/
    if (lastLog) {
        if (chainedParentNull) {
            isItToBeLogged = (ruleMessage->m_saveMessage && (m_chainedRuleParent == nullptr));
            if (isItToBeLogged && !hasMultimatch()) {
                /* warn */
                trans->m_rulesMessages.push_back(*ruleMessage);
                trans->serverLog(ruleMessage);

                /* error
                if (!ruleMessage->m_isDisruptive) {
                    trans->serverLog(ruleMessage);
                }*/
            }
        } else if (hasBlockAction() && !hasMultimatch()) {
            /* warn */
            trans->m_rulesMessages.push_back(*ruleMessage);
            trans->serverLog(ruleMessage);
            /* error
            if (!ruleMessage->m_isDisruptive) {
                trans->serverLog(ruleMessage);
            }*/
        } else {
            if (isItToBeLogged && !hasMultimatch()
                && !ruleMessage->m_message.empty()) {
                /* warn */
                trans->m_rulesMessages.push_back(*ruleMessage);
                trans->serverLog(ruleMessage);

                /* error
                if (!ruleMessage->m_isDisruptive) {
                    trans->serverLog(ruleMessage);
                } */
            }
        }
    } else {
        if (hasMultimatch() && isItToBeLogged) {
            /* warn */
            trans->m_rulesMessages.push_back(*ruleMessage.get());
            trans->serverLog(ruleMessage);

            /* error
            if (!ruleMessage->m_isDisruptive) {
                trans->serverLog(ruleMessage);
            } */

            RuleMessage *rm = new RuleMessage(this, trans);
            rm->m_saveMessage = ruleMessage->m_saveMessage;
            ruleMessage.reset(rm);
        }
    }
}

Was really hoping that would do the trick of printing the warning messages out to webserver log.

[jeremyjpj0916]

Update, airween made the point to see the Warning logs I must run NGX in debug mode, then they will appear with INFO level. This is true. Now my goal for part 1. is to change ModSecurities behavior from logging them as INFO to rather logging them as NOTICE or ERROR. Makes no sense but its how I run in production and I need these logs to not get lost.

https://github.com/SpiderLabs/ModSecurity-nginx/blob/master/src/ngx_http_modsecurity_log.c#L33

AH HA, can be done here by setting to _ERR or whatever I want. Part 1 solved.

[jeremyjpj0916]

Last part 2 is how to elegantly force ModSecurity or the ModSecurity-Nginx connector to ONLY Audit log file when a TX was blocked by the WAF, OR if a TX WOULD have been blocked by the WAF(when in DetectionOnly mode). Any easy snippits in the src I can edit to achieve this?

[jeremyjpj0916]

Actually part 2 works fine it seems when I remove the status options associated with audit logging. closing this.