Msg/Logdata block misrepresented in JSON audit log matched_rules block

[dune73]

The following rule:

SecRule ARGS:test "."   "id:1006,phase:2,pass,log,msg:'HIT: %{MATCHED_VAR}',logdata:'Matched Data: %{TX.0} found within %{MATCHED_VAR_NAME}: %{MATCHED_VAR}'"

Results in the following audit log block:

...
        {
            "chain": false,
            "rules": [
                {
                    "actionset": {
                        "id": "1006",
                        "is_chained": false,
                        "logdata": "Matched Data: /etc/passwd found within REMOTE_ADDR: 127.0.0.1",
                        "msg": "HIT: 127.0.0.1",
                        "phase": 2
                    },
                    "config": {
                        "filename": "/apache/conf/httpd.conf_pod_2016-06-28_06:13",
                        "line_num": 233
                    },
                    "is_matched": true,
                    "operator": {
                        "negated": false,
                        "operator": "rx",
                        "operator_param": ".",
                        "target": "ARGS:test"
                    },
                    "unparsed": "SecRule \"ARGS:test\" \"@rx .\" \"phase:2,id:1006,pass,log,msg:'HIT: %{MATCHED_VAR}',logdata:'Matched Data: %{TX.0} found within %{MATCHED_VAR_NAME}: %{MATCHED_VAR}'\""
                }
            ]
        },
...

msg and logdata are obviously wrong.

If you look at the native alert, it is perfectly ok:

[2016-06-28 06:19:00.628478] [-:error] 127.0.0.1:59413 V3H6tH8AAQEAADNUhysAAAAA [client 127.0.0.1] ModSecurity: Warning. Pattern match "." at ARGS:test. [file "/apache/conf/httpd.conf_pod_2016-06-28_06:13"] [line "233"] [id "1006"] [msg "HIT: /etc/passwd"] [data "Matched Data:  found within ARGS:test: /etc/passwd"] [hostname "localhost"] [uri "/index.html"] [unique_id "V3H6tH8AAQEAADNUhysAAAAA"]

[zimmerle]

Hi @dune73,

Thanks for the report. Let me add @p0pr0ck5 to the loop, he may know by heart what is going on.

[p0pr0ck5]

@dune73 do you have any other rules that are matching when this audit log entry is written? I ask because at initial glance I would guess this is happening because macro expansion of msg and logdata is occurring when sec_audit_logger is called at the end of phase 5, and %{MATCHED_VAR} and %{MATCHED_VAR_NAME} have different elements, so they are expanded "properly", but not to the value expected to be associated with that rule.

The second entry you attached is an Apache error log entry, not an audit log entry. When an alert is written to the error log, msc_alert_message is called, which in turn calls msre_format_metadata, where logdata and msg are interpolated. This happens immediately after the rule is matched (see apache2/re.c:2551) If another rule matches after these calls are made, the above noted macros would have altered values. I would expect the alert block in the JSON blob for that audit log entry to contain the correct value.

Perhaps something to take away from this is that macro expansion of individual rules in JSON is of limited value because of this behavior.

[dune73]

Thank you for your explanation @p0pr0ck5. I think I understand why this happens. But I think it is not useable the way it is:

Config:

SecAuditLogParts              ABEFHIJKZ
SecAuditLogFormat             JSON
...
SecRule REQUEST_URI "." "id:1004,phase:2,pass,log,msg:'request_uri: %{MATCHED_VAR}'"
SecRule ARGS_GET:p_get "."  "id:1005,phase:2,pass,log,msg:'p_get: %{MATCHED_VAR}'"
SecRule ARGS_POST:p_post "."    "id:1006,phase:2,pass,log,msg:'p_post: %{MATCHED_VAR}'"

Call:

$> curl http://localhost/index.html?p_get=foo -d "p_post=bar"

Native Audit Log:

--296d1b76-H--
Message: Warning. Pattern match "." at REQUEST_URI. [file "/apache/conf/httpd.conf_pod_2016-06-29_20:31"] [line "128"] [id "1004"] [msg "request_uri: /index.html?p_get=foo"]
Message: Warning. Pattern match "." at ARGS_GET:p_get. [file "/apache/conf/httpd.conf_pod_2016-06-29_20:31"] [line "130"] [id "1005"] [msg "p_get: foo"]
Message: Warning. Pattern match "." at ARGS_POST:p_post. [file "/apache/conf/httpd.conf_pod_2016-06-29_20:31"] [line "132"] [id "1006"] [msg "p_post: bar"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Stopwatch: 1467225504520970 3262 (- - -)
Stopwatch2: 1467225504520970 3262; combined=963, p1=19, p2=819, p3=17, p4=17, p5=90, sr=0, sw=1, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.9.1 (http://www.modsecurity.org/).
Server: Apache
Engine-Mode: "ENABLED"

--296d1b76-K--
SecRule "REQUEST_URI" "@rx ." "phase:2,id:1004,pass,log,msg:'request_uri: %{MATCHED_VAR}'"
SecRule "ARGS_GET:p_get" "@rx ." "phase:2,id:1005,pass,log,msg:'p_get: %{MATCHED_VAR}'"
SecRule "ARGS_POST:p_post" "@rx ." "phase:2,id:1006,pass,log,msg:'p_post: %{MATCHED_VAR}'"

JSON Audit Log:

"audit_data": {
    "engine_mode": "ENABLED",
    "error_messages": [
        "[file \"apache2_util.c\"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri \"%s\"]%s",
        "[file \"apache2_util.c\"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri \"%s\"]%s",
        "[file \"apache2_util.c\"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri \"%s\"]%s"
    ],
    "messages": [
        "Warning. Pattern match \".\" at REQUEST_URI. [file \"/apache/conf/httpd.conf_pod_2016-06-29_20:31\"] [line \"129\"] [id \"1004\"] [msg \"request_uri: /index.html?p_get=foo\"]",
        "Warning. Pattern match \".\" at ARGS_GET:p_get. [file \"/apache/conf/httpd.conf_pod_2016-06-29_20:31\"] [line \"131\"] [id \"1005\"] [msg \"p_get: foo\"]",
        "Warning. Pattern match \".\" at ARGS_POST:p_post. [file \"/apache/conf/httpd.conf_pod_2016-06-29_20:31\"] [line \"133\"] [id \"1006\"] [msg \"p_post: bar\"]"
    ],
    "producer": "ModSecurity for Apache/2.9.1 (http://www.modsecurity.org/)",
    "response_body_dechunked": true,
    "server": "Apache",
    "stopwatch": {
        "gc": 0,
        "l": 0,
        "p1": 18,
        "p2": 789,
        "p3": 16,
        "p4": 16,
        "p5": 50,
        "sr": 0,
        "sw": 0
    }
},
"matched_rules": [
    {
        "chain": false,
        "rules": [
        {
            "actionset": {
            "id": "1004",
            "is_chained": false,
            "msg": "request_uri: bar",
            "phase": 2
            },
            "config": {
            "filename": "/apache/conf/httpd.conf_pod_2016-06-29_20:31",
            "line_num": 129
            },
            "is_matched": true,
            "operator": {
            "negated": false,
            "operator": "rx",
            "operator_param": ".",
            "target": "REQUEST_URI"
            },
            "unparsed": "SecRule \"REQUEST_URI\" \"@rx .\" \"phase:2,id:1004,pass,log,msg:'request_uri: %{MATCHED_VAR}'\""
        }
        ]
    },
    {
        "chain": false,
        "rules": [
        {
            "actionset": {
            "id": "1005",
            "is_chained": false,
            "msg": "p_get: bar",
            "phase": 2
            },
            "config": {
            "filename": "/apache/conf/httpd.conf_pod_2016-06-29_20:31",
            "line_num": 131
            },
            "is_matched": true,
            "operator": {
            "negated": false,
            "operator": "rx",
            "operator_param": ".",
            "target": "ARGS_GET:p_get"
            },
            "unparsed": "SecRule \"ARGS_GET:p_get\" \"@rx .\" \"phase:2,id:1005,pass,log,msg:'p_get: %{MATCHED_VAR}'\""
        }
        ]
    },
    {
        "chain": false,
        "rules": [
        {
            "actionset": {
            "id": "1006",
            "is_chained": false,
            "msg": "p_post: bar",
            "phase": 2
            },
            "config": {
            "filename": "/apache/conf/httpd.conf_pod_2016-06-29_20:31",
            "line_num": 133
            },
            "is_matched": true,
            "operator": {
            "negated": false,
            "operator": "rx",
            "operator_param": ".",
            "target": "ARGS_POST:p_post"
            },
            "unparsed": "SecRule \"ARGS_POST:p_post\" \"@rx .\" \"phase:2,id:1006,pass,log,msg:'p_post: %{MATCHED_VAR}'\""
        }
        ]
    }
],

Matched_rules looks like Native Part K, then you give the unparsed rule correctly and then
an expanded version of the rule with macro expansion in phase 5, which results in bogus
output.

I have the messages correctly expanded (and partially escaped) in audit_data->messages that looks
a lot like H. But here the rules are not expanded. So the benefit of the JSON format is mostly gone.

I see a quick fix by removing msg and data from the expanded rules in matched_rules the they are
bogus.
And I see a real benefit in adding the expansion including msg and data in audit_data instead.

[p0pr0ck5]

I do believe that removing msg and logdata from the rules element in matched_rules is worthwhile, since it doesn't serve a lot of value in this case.

So you think we should add another pair of keys in audit_data to hold the expanded msg/logdata elements? Or how should this be formatted? I agree that the contents from the error message are not consumable, I'm just wondering what the best way to represent this data is without a lot of unnecessary duplication.

An alternative for now is to create separate variables in the TX collection to use for this kind of tracking

[dune73]

I am skeptical of pushing more into additional variables. But maybe you can extract out of the data structure you need for audit_data. As the audit log is written in a single batch, that stuff must still be around.

[p0pr0ck5]

That's what I'm saying though, if you overwrite a variable, it's previous value isn't stored anywhere. If we wanted to hold each macro-expanded msg and logdata entry throughout the lifetime of the transaction, created with the value of the associated variables at the time of the rule match (like Apache error logs are created), we'd have to create a new apr array to hold this data (and we'd essentially be duplicating the msr->alerts table)

[dune73]

ACK

[p0pr0ck5]

Have we figured out the best approach here?

[dune73]

I'd either leave it away for good or extract the info out of msr->alerts. But I do not know the code as well as you do.

[p0pr0ck5]

As msr->alerts only has the parsed out string, I think we'll just have to do without for now. Interested to see what the differences in the v3 JSON look like and how these situations are handled.

I'll have a PR up to remove this flawed data next week.

[dune73]

Fair with me.