Only the last match of a rule is logged

[WGH-]

This program

#include <memory>
#include <iostream>

#include <modsecurity/modsecurity.h>
#include <modsecurity/rules_set.h>
#include <modsecurity/rule_message.h>

int main(void) {
    auto modsec = std::make_unique<modsecurity::ModSecurity>();
    auto rules = std::make_unique<modsecurity::RulesSet>();

    int res = rules->load(R"EOM(
        SecRule ARGS \
            "@rx bash" \
            "id:1,\
            phase:1,\
            block"
    )EOM");
    if (res < 0) {
        std::cerr << rules->getParserError() << std::endl;
        return 1;
    }

    modsec->setServerLogCb([](void *p, const void *msg) {
       auto rm = static_cast<const modsecurity::RuleMessage*>(msg);
        std::cerr << rm->m_match << std::endl;
    }, modsecurity::RuleMessageLogProperty);

    auto transaction = std::make_unique<modsecurity::Transaction>(modsec.get(), rules.get(), nullptr);

    transaction->processConnection("127.0.0.1", 12345, "127.0.0.1", 80);
    transaction->processURI("/?arg1=bash&arg2=bash", "GET", "1.1");
    transaction->processRequestHeaders();
    transaction->processRequestBody();

    return 0;
}

prints out a single message

Matched "Operator `Rx' with parameter `bash' against variable `ARGS:arg2' (Value: `bash' )`.

even though the rule matches both query arguments.

This is the place where the operator is applied to every variable.

https://github.com/SpiderLabs/ModSecurity/blob/50fc347ed4d0852d54561e15559de07c698fbb16/src/rule_with_operator.cc#L310-L332

Note that there is performLogging call. It doesn't log anything here, because lastLog=false, hasMultimatch()=false.

The actual logging only happens at the end of RuleWithOperator::evaluate, which logs only a single message. ruleMessage->m_match is overwritten in the loop above, so only the last matching variable is effectively logged.

Is this something intented? My colleagues say that ModSecurity v2 used to log all rule matches in the same scenario.

[zimmerle]

Hi, @WGH-,

That is an interesting observation. Indeed that is what to expect on mod_security (2.x) -

[Thu Feb 11 14:15:21.980420 2021] [:error] [pid 17670] [client ::1:58382] [client ::1] ModSecurity: Warning. Pattern match "bash" at ARGS:arg1. [file "/etc/httpd/conf/httpd.conf"] [line "552"] [id "1"] [hostname "localhost"] [uri "/"] [unique_id "YCVmKRR2j9G1-vMqSelO8QAAAAE"]
[Thu Feb 11 14:15:21.980455 2021] [:error] [pid 17670] [client ::1:58382] [client ::1] ModSecurity: Warning. Pattern match "bash" at ARGS:arg2. [file "/etc/httpd/conf/httpd.conf"] [line "552"] [id "1"] [hostname "localhost"] [uri "/"] [unique_id "YCVmKRR2j9G1-vMqSelO8QAAAAE"]

As opposed to the last hit on v3 -

(...) Matched "Operator `Rx' with parameter `bash' against variable `ARGS:arg2' (Value: `bash' )`

(a) We aim to reduce the amount of logging that goes over the error log. (b) Having a more meaningful log;

On the error log, we want to justify why a certain disruptive action was taken. In the case of a given rule with more than one non excluding reason, v3 kept the first or last.

Ideally, we would like to have a single log entry explain that a second (or n) match also occurred. As opposed to multiple lines that tricks the user into interpreting a and or or. As you noticed, that is a WiP.

Is the missing log entry is an issue for you?

[WGH-]

Yes. We use ModSecurity as a library, and we need info about every match to make a better decision. For example, some matches of a rule might be false positives, so if only one match is reported, we lose information.

[zimmerle]

Yes. We use ModSecurity as a library, and we need info about every match to make a better decision. For example, some matches of a rule might be false positives, so if only one match is reported, we lose information.

If I understood it right, I am afraid that the described use case was not considered while the library was being defined.

It seems that you use the intervention output (logging) as input to a 3rd party software to decide whatever action you will be taken. That ignores the default actions from ModSecurity and place the logic outside ModSecurity. Is it the case?

[WGH-]

It seems that you use the intervention output (logging) as input to a 3rd party software to decide whatever action you will be taken. That ignores the default actions from ModSecurity and place the logic outside ModSecurity. Is it the case?

Pretty much, yes.