Fix apache logging limitation by using correct apache call.

[dune73]

Apache 2.4 brought the option to change the ErrorLogFormat. However, many fields remain empty, as ModSecurity uses the wrong apache logging function. This fixes this behaviour with the use of ap_log_rerror.

[zimmerle]

Hi @dune73 ,

Sent your patch to our buildbots last Friday. It seems like it won't compile to Nginx (32 or 64), same for IIS (Windows 7 and 8, 32 and 64 bits).

Look at the buildbot results here:

• Nginx (Linux 32) - http://www.modsecurity.org/developers/buildbot/builders/Linux32%20-%20Nginx%20%28Mainline%29/builds/180/steps/make%20nginx/logs/stdio
• Ningx (Linux 64) - http://www.modsecurity.org/developers/buildbot/builders/Linux64%20-%20Nginx%20%28Mainline%29/builds/198/steps/make%20nginx/logs/stdio
• Windows 8 - vs2012 - http://www.modsecurity.org/developers/buildbot/builders/Win8%20-%20%28VS%202012%2064b%29%20-%20IIS/builds/152/steps/build%20modsec/logs/stdio

The complete list is available here: http://www.modsecurity.org/developers/buildbot/waterfall

The problem seems to be the same:

undefined reference to `ap_log_rerror_'

We may need to define the method ap_log_rerror in standalone as well, like ap_log_error is defined here: https://github.com/SpiderLabs/ModSecurity/blob/4a49d5b8dc4346d7583c66be4579309d0259827c/standalone/server.c#L263-L286

[dune73]

OK. I'll try and sort this out. Please hold on.

[zimmerle]

thank you @dune73

[dune73]

So this took a while, but now I added the said declaration to standalone/server.c. NginX compiles for me now.

[zimmerle]

Thanks @dune73, I will have a look later today.

[zimmerle]

Thanks @dune73!

Patch merged!

[dune73]

The thanks is all yours, @zimmerle.

[tunetheweb]

@rainerjung, @dune73 What does this mean?:

If you apply the patch, you might also want to remove the "[client %s] " part of your log format (and the corresponding ip address argument) since it is redudant to what ap_log_rerror() already writes out by default.

I'm using 2.9.1-RC1, specifically for this change, and I do notice it's now logging the client IP twice: once as part of the standard apache ErrorLogFormat (with text "client", client ip address and port), and ModSecurity seems to be logging it again in error log just before it's message (with text "client", client ip address and no port):

[Sun Feb 21 23:14:34.453580 2016] [:error] [pid 7979:tid 140254355486464] [client 1.2.3.4:52788] [client 1.2.3.4] ModSecurity: Access denied with code 403 (phase 2)...etc.

Now I can of course change this in ErrorLogFormat now thanks to this change, to stop logging the client ip address and port, but then this will remove it from all error logging and not just ModSecurity error logging. Surely this duplication should be removed in ModSecurity?

Not a massive deal, and if can't be fixed will live with it for this extra functionality, but a little confusing none-the-less.

[dune73]

This is odd.

There is redundancy in the default logformat, but I do not see a duplication like you. Here is an example from my 2.9.1-rc1 tests with default ErrorLogFormat:

[2016-02-22 05:13:42.442421] [-:error] 127.0.0.1:59593 VsqK9n8AAQEAAB9HHJQAAAAA [client 127.0.0.1] ModSecurity: Warning. Matched phrase "/etc/passwd" at ARGS:y. [file "/home/dune73/data/git/owasp-modsecurity-crs-dune73/rules/REQUEST-30-APPLICATION-ATTACK-LFI.conf"] [line "108"] [id "930120"] [rev "4"] [msg "OS File Access Attempt"] [data "Matched Data: /etc/passwd found within ARGS:y: /etc/passwd"] [severity "CRITICAL"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "9"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-local file inclusion"] [tag "OWASP_CRS/WEB_ATTACK/FILE_INJECTION"] [tag "WASCTC/WASC-33"] [tag "OWASP_TOP_10/A4"] [tag "PCI/6.5.4"] [hostname "localhost"] [uri "/index.html"] [unique_id "VsqK9n8AAQEAAB9HHJQAAAAA"]

But where is your 1st "[client ..." is coming from? Do you have a custom ErrorLogFormat configured?

I think Felipe did not want to remove the redundancy as it could kill existing installations which take the info out of the ModSec part of the log. But I can not really tell for sure. My patch was only about enabling apache to fill its part of the log.

[tunetheweb]

Well I tried it both with a defined ErrorLogFormat (set to the same as the default) and then with no ErrorLogFormat specified at all.

It's interesting that your log snippet logs the client IP twice. Just the first time without the "client" label and without the square brackets. As these are the defaults in Apache log files I've got to ask - are sure you don't have a custom ErrorLogFormat defined? ;-)

[dune73]

Thanks for following up. Indeed, I edited the wrong config file. I can now confirm your finding:

[Mon Feb 22 09:29:19.502412 2016] [:error] [pid 13241:tid 140224330340096] [client 127.0.0.1:33041] [client 127.0.0.1] ModSecurity: ...

@zimmerle : What do we do with this? I suggest to remove the ModSec repetition of the client IP, but maybe that is risky as apache is adding the port number as well. Maybe we can cope with that by proposing a custom ErrorLogFormat in the CHANGES file which brings the apache part of the entry without the port number. I guess this is what @rainerjung proposed all along.

[MichaelHaas]

since 2.9.1-RC1 i get for each entry in the audit log the following error. Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s Is this a side effect of this change?

[dune73]

@MichaelHaas I do not think so. But then your problem was not there with 2.9.0 (?), so it must have to do with 2.9.1-rc1.

Could you provide more infos?

• Apache Version / Build infos
• Full ErrorLog Line (possibly more logs like a full request on LogLevel trace8)
• Config File

[MichaelHaas]

Problem started with 2.9.1-rc1. It was not there with 2.7.7 or 2.9.0. Apache 2.4.17 (tested also 2.4.18) I only get this error when Loglevel is set >=error so if i set it to crit the error/message is not there.

--a7c7313d-B-- GET /?select * from SYSTEM.TEST HTTP/1.1 User-Agent: curl/7.19.7 (x8664-suse-linux-gnu) libcurl/7.19.7 OpenSSL/0.9.8j zlib/1.2.7 libidn/1.10 Host: xxxxx Accept: /_

--a7c7313d-F-- HTTP/1.1 403 Forbidden Accept-Ranges: bytes Connection: close Content-Type: text/html

--a7c7313d-H-- Message: Match of "rx ^(?i:(?:[a-z]{3,10}\s+(?:\w{3,7}?://[\w-./](?::\d+)?)?/[^?#](?:\?[^#\s])?(?:#[\S])?|connect (?:\d{1,3}.){3}\d{1,3}.?(?::\d+)?|options _)\s+[\w./]+|get /[^?#](?:\?[^#\s])?(?:#[\S]_)?)$" against "REQUEST_LINE" required. [file "xxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_20_protocol_violations.conf"] [line "52"] [id "960911"] [rev "2"] [msg "Invalid HTTP Request Line"] [data "GET /?select * from SYSTEM.TEST HTTP/1.1"] [severity "WARNING"] [ver "OWASP_CRS/2.2.8"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ"] [tag "CAPEC-272"] Message: Match of "within %{tx.allowed_http_versions}" against "REQUEST_PROTOCOL" required. [file "xxxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_30_http_policy.conf"] [line "78"] [id "960034"] [rev "2"] [msg "HTTP protocol version is not allowed by policy"] [data "* from SYSTEM.TEST HTTP/1.1"] [severity "CRITICAL"] [ver "OWASP_CRS/2.2.8"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/POLICY/PROTOCOL_NOT_ALLOWED"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A6"] [tag "PCI/6.5.10"] Message: Access denied with code 403 (phase 2). Pattern match "(.)" at TX:960911-OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ-REQUEST_LINE. [file "xxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_49_inbound_blocking.conf"] [line "26"] [id "981176"] [msg "Inbound Anomaly Score Exceeded (Total Score: 5, SQLi=1, XSS=0): Last Matched Message: HTTP protocol version is not allowed by policy"] [data "Last Matched Data: GET /?select \ from SYSTEM.TEST HTTP/1.1"] Message: Warning. Operator GE matched 5 at TX:inbound_anomaly_score. [file "xxxxxx/conf/modsecurity_crs/activated_rules/modsecurity_crs_60_correlation.conf"] [line "37"] [id "981204"] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 5, SQLi=1, XSS=0): HTTP protocol version is not allowed by policy"] 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 Action: Intercepted (phase 2) Stopwatch: 1456753685799877 3072 (- - -) Stopwatch2: 1456753685799877 3072; combined=1597, p1=348, p2=1120, p3=0, p4=0, p5=129, sr=0, sw=0, l=0, gc=0 Producer: ModSecurity for Apache/2.9.1-RC1 (http://www.modsecurity.org/); OWASP_CRS/2.2.8. Server: Apache Engine-Mode: "ENABLED"

--a7c7313d-Z--

If i set the loglevel to trace8 i get more errors/messages.

--585cd533-H-- Message: Match of "rx ^(?i:(?:[a-z]{3,10}\s+(?:\w{3,7}?://[\w-./](?::\d+)?)?/[^?#](?:\?[^#\s])?(?:#[\S])?|connect (?:\d{1,3}.){3}\d{1,3}.?(?::\d+)?|options _)\s+[\w./]+|get /[^?#](?:\?[^#\s])?(?:#[\S]_)?)$" against "REQUEST_LINE" required. [file "xxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_20_protocol_violations.conf"] [line "52"] [id "960911"] [rev "2"] [msg "Invalid HTTP Request Line"] [data "GET /?select * from SYSTEM.TEST HTTP/1.1"] [severity "WARNING"] [ver "OWASP_CRS/2.2.8"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ"] [tag "CAPEC-272"] Message: Match of "within %{tx.allowed_http_versions}" against "REQUEST_PROTOCOL" required. [file "xxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_30_http_policy.conf"] [line "78"] [id "960034"] [rev "2"] [msg "HTTP protocol version is not allowed by policy"] [data "* from SYSTEM.TEST HTTP/1.1"] [severity "CRITICAL"] [ver "OWASP_CRS/2.2.8"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/POLICY/PROTOCOL_NOT_ALLOWED"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A6"] [tag "PCI/6.5.10"] Message: Access denied with code 403 (phase 2). Pattern match "(.)" at TX:960911-OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ-REQUEST_LINE. [file "xxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_49_inbound_blocking.conf"] [line "26"] [id "981176"] [msg "Inbound Anomaly Score Exceeded (Total Score: 5, SQLi=1, XSS=0): Last Matched Message: HTTP protocol version is not allowed by policy"] [data "Last Matched Data: GET /?select \ from SYSTEM.TEST HTTP/1.1"] Message: Warning. Operator GE matched 5 at TX:inbound_anomaly_score. [file "xxxxxx/apache_test/conf/modsecurity_crs/activated_rules/modsecurity_crs_60_correlation.conf"] [line "37"] [id "981204"] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 5, SQLi=1, XSS=0): HTTP protocol version is not allowed by policy"] Apache-Error: [file "ssl_engine_kernel.c"] [line 245] [level 7] AH02034: %s HTTPS request received for child %ld (server %s) Apache-Error: [file "http_request.c"] [line 322] [level 11] Headers received from client: Apache-Error: [file "http_request.c"] [line 326] [level 11] %s: %s Apache-Error: [file "http_request.c"] [line 326] [level 11] %s: %s Apache-Error: [file "http_request.c"] [line 326] [level 11] %s: %s Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s Apache-Error: [file "request.c"] [line 293] [level 10] request authorized without authentication by access_checker_ex hook: %s Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s Apache-Error: [file "request.c"] [line 349] [level 10] fixups hook gave %d: %s Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s Apache-Error: [file "request.c"] [line 293] [level 10] request authorized without authentication by access_checker_ex hook: %s Apache-Error: [file "http_filters.c"] [line 1006] [level 10] Response sent with status %d%s Apache-Error: [file "http_filters.c"] [line 1013] [level 12] Date: %s Apache-Error: [file "http_filters.c"] [line 1016] [level 12] Server: %s Apache-Error: [file "http_filters.c"] [line 835] [level 11] %s: %s Apache-Error: [file "http_filters.c"] [line 835] [level 11] %s: %s Apache-Error: [file "http_filters.c"] [line 835] [level 11] %s: %s Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s

Configure option are normal i think.

./configure \ --prefix=$installdir \ --with-apxs=$apachedir/bin/apxs \ --with-apr=$apachedir/bin/apr-1-config \ --with-apu=$apachedir/bin/apu-1-config \ --disable-mlogc \ --with-curl=no

You don't get these Messages at all with 2.9.2rc1?

[MichaelHaas]

I changed ap_log_rerror(APLOG_MARK, APLOG_ERR | APLOG_NOERRNO, 0, r, back to ap_log_error(APLOG_MARK, APLOG_ERR | APLOG_NOERRNO, 0, r->server, and now the message is gone.

[dune73]

Too bad.

I planned to do exactly that, but a customer project keeps me busy.

The patch was built a long time ago and I do not have the logs ready. So I can not really tell what happened when I enabled it. Based on your report and given the ModSec dev community meeting talking about 2.9.1 release will be tomorrow (care to join?) it might be best to pull this change out of the release. After all it's a final release for 2.9 and we do not have the option to fix it in an eventual 2.9.2.

[tunetheweb]

Disappointing, and didn't see that error myself but probably right call since there are a few outstanding questions and getting late in the day.

I was looking for this change to start logging the real IP address (in X-FORWARDED-FOR header) in error logs as our Apache sits behind a load balancer. Any other thoughts on how I could do this?

Thanks, Barry

On 1 Mar 2016, at 13:44, Christian Folini notifications@github.com wrote:

Too bad.

I planned to do exactly that, but a customer project keeps me busy.

The patch was built a long time ago and I do not have the logs ready. So I can not really tell what happened when I enabled it. Based on your report and given the ModSec dev community meeting talking about 2.9.1 release will be tomorrow (care to join?) it might be best to pull this change out of the release. After all it's a final release for 2.9 and we do not have the option to fix it in an eventual 2.9.2.

— Reply to this email directly or view it on GitHub.

[MichaelHaas]

Seems like i'm not the only one issue #1073 was opened by @lifeforms. Have tried to change the ap_log_rerror statement and removed all %s but it didn't help. I think it's best to revert the change because i'm not a programmer and can't fix it.

[tunetheweb]

Actually you are correct. That is there in the audit logs - hadn't noticed this before as thought you meant it wasn't logging the real error.

You can fix this by commenting out or removing line 1989 of msc_logging.c to stop logging this to the audit log since it really is a useless message:

    for(i = 0; i < msr->error_messages->nelts; i++) {
        error_message_t *em = (((error_message_t **)msr->error_messages->elts)[i]);
        text = apr_psprintf(msr->mp, "Apache-Error: %s\n",
            format_error_log_message(msr->mp, em));
           /* sec_auditlog_write(msr, text, strlen(text)); */
    }

I would submit a pull request but not that familiar with Git to be honest!

Looks like this was always there but is only now being called as a side effect to this change.

[dune73]

Hold on, you are suppressing the Apache-Error messages from the audit log, are not you? Also the ones which are correctly formatted.

[MichaelHaas]

wouldn't this remove all Apache-Error messages? Sometimes they are helpful, for example if apache denied a request and you have it logged in the audit log you see something like this Apache-Error: [file "mod_authz_host.c"] [line 311] [level 3] client denied by server configuration: ... So you can see immediately that apache denied the request.

[tunetheweb]

Hmmm yes it would. A little bit of knowledge is a dangerous thing!

Looks like they are not correctly formatted anyway. For example:

Apache-Error: [file "core.c"] [line 4302] [level 3] AH00126: Invalid URI in request %s

But if people find them useful then I'm easy either way. Leave in and ignore this extra ModSecurity error, or exclude and lose all the messages. Personally I'd probably leave in.

[dune73]

So I sat down and tried to nail this occurrence of "%s" artifacts in the auditlog. I was able to isolate them from this pull request.

Here is the audit log of ModSecurity 2.7.5 on Apache 2.4.18:

--30a40174-H--
Message: Warning. Pattern match "(?:(?<!\\w)(?:\\.(?:ht(?:access|passwd|group)|www_?acl)|global\\.asa|httpd\\.conf|boot\\.ini)\\b|\\/etc\\/)" at ARGS:a. [file "/core-rules/modsecurity_crs_40_generic_attacks.conf"] [line "205"] [id "950005"] [rev "3"] [msg "Remote File Access Attempt"] [data "Matched Data: /etc/ found within ARGS:a: /etc/passwd"] [severity "CRITICAL"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/WEB_ATTACK/FILE_INJECTION"] [tag "WASCTC/WASC-33"] [tag "OWASP_TOP_10/A4"] [tag "PCI/6.5.4"
Message: Warning. Operator LT matched 500 at TX:inbound_anomaly_score. [file "/core-rules/modsecurity_crs_60_correlation.conf"] [line "33"] [id "981203"] [msg "Inbound Anomaly Score (Total Inbound Score: 5, SQLi=, XSS=): Remote File Access Attempt"]
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "core.c"] [line 4433] [level 6] AH00128: File does not exist: %s
Stopwatch: 1457442539179655 5578 (- - -)`
Stopwatch2: 1457442539179655 5578; combined=3790, p1=645, p2=1952, p3=82, p4=303, p5=807, sr=147, sw=1, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.7.5 (http://www.modsecurity.org/).
Server: Apache
Engine-Mode: "ENABLED"

So I think it is save to conclude this is a new apache issue or an issue in msc_logging.c, but rather not one introduced by pull request 840. However, @MichaelHaas says it was not there in previous versions, but I think he must be wrong.

[tunetheweb]

AFAIK it was always there for the other modules, but that's not what @MichaelHaas is raising. There is one extra line now for the ModSecurity error in the audit log.

So, prior to 2.9.1-RC1 it used to say:

Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "core.c"] [line 4433] [level 6] AH00128: File does not exist: %s

with the %s not being filled in.

and now it says:

Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "core.c"] [line 4433] [level 6] AH00128: File does not exist: %s
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s

with the %s not being filled in and an extra line for ModSecurity now, since it is now going through the proper apache error logging thanks to this change.

To me if you're dealing with the other messages already then one extra message for ModSecurity is not a big deal. But that's just me, because I never noticed them or used them before (and hence didn't even see what @MichaelHaas was talking about initially!). And because I want this change for other reasons :-)

[MichaelHaas]

These are new Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s I don't have them in the audit log before 2.9.1. I found now some other with 2.9.0 Apache-Error: [file "proxy_util.c"] [line 3366] [level 4] AH01092: no HTTP 0.9 request (with no host line) on incoming request and preserve host set forcing hostname to be %s for uri %s I think the problem with the new one is that it logs them with each message so you have them always in the log. But if it's only a problem for me i can live with it ;).

[MichaelHaas]

I think i didn't see them in my logs because for example this messages is only shown when you are not denying the request. Apache-Error: [file "core.c"] [line 4433] [level 6] AH00128: File does not exist: %s If mod_security is blocking the request then you don't see them.

[tunetheweb]

Depends on the phase and the request.

For example ModSecurity can actually _start _to block based on these messages - see rule 981227 in OWASP CRS for example:

#
# Identify Invalid URIs Blocked by Apache 
#
# -=[ Rule Logic ]=-
#
# There are some request violations that Apache will handle internally, prior to the
# ModSecurity phase:1 POST-READ-REQUEST hook.  For these requests, we can still get
# visibility by running a check in phase:5 logging to look for the Apache error msg.
#
# -=[ References ]=-
#
SecRule WEBSERVER_ERROR_LOG "@contains Invalid URI in request" \
  "msg:'Apache Error: Invalid URI in Request.', \
  severity:'4', \
  id:'981227', \
  ver:'OWASP_CRS/2.2.9', \
  rev:'1', \
  maturity:'9', \
  accuracy:'9', \
  logdata:'%{request_line}', \
  phase:5, \
  pass, \
  t:none, \
  tag:'OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ', \
  tag:'CAPEC-272', \
  setvar:'tx.msg=%{rule.msg}', \
  setvar:tx.anomaly_score=+%{tx.notice_anomaly_score}, \
  setvar:'tx.%{rule.id}-OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ-%{matched_var_name}=%{matched_var}'"

Which can result in this:

--8896924b-H--
Message: Warning. String match "Invalid URI in request" at WEBSERVER_ERROR_LOG. [file "/www/apache24/conf/modsecurity.d/crs/owasp-modsecurity-crs/base_rules/modsecurity_crs_20_protocol_violations.conf"] [line "82"] [id "981227"] [rev "1"] [msg "Apache Error: Invalid URI in Request."] [data "GET //../../../../../../../../../../../../../../winnt/win.ini HTTP/1.1"] [severity "WARNING"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/INVALID_REQ"] [tag "CAPEC-272"]
Apache-Error: [file "core.c"] [line 4302] [level 3] AH00126: Invalid URI in request %s
Stopwatch: 1457392965814065 1162 (- - -)
Stopwatch2: 1457392965814065 1162; combined=548, p1=236, p2=0, p3=14, p4=83, p5=215, sr=0, sw=0, l=0, gc=0
Producer: ModSecurity for Apache/2.9.0 (http://www.modsecurity.org/); OWASP_CRS/2.2.9.
Server: Apache
Engine-Mode: "ENABLED"

Also proxy errors can be intercepted to prevent data leakage:

Message: Access denied with code 403 (phase 4). Pattern match "^5\\d{2}$" at RESPONSE_STATUS. [file "/www/apache24/conf/modsecurity.d/crs/owasp-modsecurity-crs/base_rules/modsecurity_crs_50_outbound.conf"] [line "53"] [id "970901"] [rev "2"] [msg "The application is not available"] [data "Matched Data: 502 found within RESPONSE_STATUS: 502"] [severity "ERROR"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "WASCTC/WASC-13"] [tag "OWASP_TOP_10/A6"] [tag "PCI/6.5.6"]
Message: Warning. Operator GE matched 4 at TX:outbound_anomaly_score. [file "/www/apache24/conf/modsecurity.d/crs/owasp-modsecurity-crs/base_rules/modsecurity_crs_60_correlation.conf"] [line "40"] [id "981205"] [msg "Outbound Anomaly Score Exceeded (score 4): The application is not available"]
Apache-Error: [file "mod_proxy_http.c"] [line 1310] [level 3] [status 70007] AH01102: error reading status line from remote server %s:%d
Apache-Error: [file "proxy_util.c"] [line 397] [level 3] AH00898: %s returned by %s
Action: Intercepted (phase 4)

But yeah I agree it's not common to see these errors in the Audit Log and now it is.

Changing line 1989 of msc_logging.c to below seems to block the ModSecurity messages only:

    /* Apache error messages */
    for(i = 0; i < msr->error_messages->nelts; i++) {
        error_message_t *em = (((error_message_t **)msr->error_messages->elts)[i]);
        text = apr_psprintf(msr->mp, "Apache-Error: %s\n",
            format_error_log_message(msr->mp, em));
        /* Don't log ModSecurity messages themselves */
        if(strstr(text, "ModSecurity") == NULL) {
            sec_auditlog_write(msr, text, strlen(text));
        }
    }

But a bit of a hack to just search for ModSecurity and I've not coded in C for many a year so not sure if someone with more knowledge can think of a better way...

[zimmerle]

Hi,

If I understood correctly, the '%s' in the H section was not being filled correctly even before that patch. Therefore, the only two problems of this patch/pull request are:

• Double client entry on the logs: [client 127.0.0.1:33041] [client 127.0.0.1]
• An extra ModSecurity line in the "H" section of the auditlogs

Is that right? If so, I would say that we don't have any major bug, rather, just features that needs some improvements/polishment.

The "double client entry" problem can be circumvented by the correct configurations, right @dune73? The extra line in the section "H" is just an extra data, that might not be a problem for the most of the users.

I can remove the patch, but I would prefer not to modify anything on the patch, as it may lead us to a -RC2 version. As we want to have a final release, my suggestion is to release the 2.9.1 as it is on -RC1 and as part of 2.9.2-RC1 we will take into consideration the modifications to suppress that extra message and to remove the double client entry. How that sounds?

[tunetheweb]

You have summed it up well and I would be keen to keep this in.

In the interests of honesty though I will point out two issues with your suggestion that we can remove the "double client entry" through configuration:

1. This is not available to Apache 2.2 users (the ErrorLogFormat option was only added in Apache 2.4).
2. The only option to do this is to remove the default Apache logging of [ip:port] using a custom ErrorLogFormat but this will remove that from all error logs and not just ModSecurity error logs. Which is unlikely to be desirable.

So realistically I don't think there is a work around for the "double client entry" problem if that does cause anyone any issues.

However personally I would still agree with the statement that "we don't have any major bug, rather, just features that needs some improvements/polishment" and would vote to keep this in.

[dune73]

Hi guys, sorry for taking weeks to actually understand what the deal is. I think Felipe summed it up nicely. And while I think it won't win a beauty contest with #840, it's better than before. But let's say this allows for improvement in eventual 2.9.2.

[zimmerle]

Hi Guys, thanks for the feedback.

I was looking to the issue and I managed to make a very simple patch: I simple removed the client entry. If you guys have time to test it, it will be very good. I have two releases ready: one with the patch and another one without it. So, if you manage to test it on time, and there is no other issue, we can release 2.9.1 without the double-client-entry problem.

Here is the branch with the patch applied: https://github.com/SpiderLabs/ModSecurity/tree/release_2.9.1-final

[dune73]

Hold on. This does not work.

2.9.1-final compiles just right and my quick tests blocked correctly. However, the logformat is messed up:

2.9.1rc1 on apache 2.4.8, Ubuntu 14.04, default ErrorLogFormat
[Wed Mar 09 15:36:26.497222 2016] [:error] [pid 21821:tid 140528867718912] [client 127.0.0.1:37688] [client 127.0.0.1] ModSecurity: Warning. Pattern match "(?:(?<!\\\\w)(?:\\\\.(?:ht(?:access|passwd|group)|www_?acl)|global\\\\.asa|httpd\\\\.conf|boot\\\\.ini)\\\\b|\\\\/etc\\\\/)" at ARGS:a. [file "/core-rules/modsecurity_crs_40_generic_attacks.conf"] [line "205"] [id "950005"] [rev "3"] [msg "Remote File Access Attempt"] [data "Matched Data: /etc/ found within ARGS:a: /etc/passwd"] [severity "CRITICAL"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/WEB_ATTACK/FILE_INJECTION"] [tag "WASCTC/WASC-33"] [tag "OWASP_TOP_10/A4"] [tag "PCI/6.5.4"] [hostname "localhost"] [uri "/index.html"] [unique_id "VuA06n8AAQEAAFU9o3IAAAAA"]

2.9.1-final on apache 2.4.8, Ubuntu 14.04, default ErrorLogFormat:
[Wed Mar 09 15:37:12.657681 2016] [:error] [pid 21955:tid 139969283852032] [client 127.0.0.1:37697] ModSecurity: 127.0.0.1Warning. Pattern match "(?:(?<!\\\\w)(?:\\\\.(?:ht(?:access|passwd|group)|www_?acl)|global\\\\.asa|httpd\\\\.conf|boot\\\\.ini)\\\\b|\\\\/etc\\\\/)" at ARGS:a. [file "/core-rules/modsecurity_crs_40_generic_attacks.conf"] [line "205"] [id "950005"] [rev "3"] [msg "Remote File Access Attempt"] [data "Matched Data: /etc/ found within ARGS:a: /etc/passwd"] [severity "CRITICAL"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/WEB_ATTACK/FILE_INJECTION"] [tag "WASCTC/WASC-33"] [tag "OWASP_TOP_10/A4"] [tag "PCI/6.5.4"] [uri " [hostname "localhost"]"]/index.html

Also the unique_id is no longer visible.

Sorry for the bad news.

[zimmerle]

My bad. It is now fixed. The fixed version is on the same branch. Do you mind to test it again?

[zimmerle]

Right, I am cooking the final release without the fix. It will be integrated as part of v2.9.2

[bitsofinfo]

Can someone please summarize what exactly if any are the changes to the format of the audit log from this patch? Would anyone who has consumers of the existing audit log format now break after this patch?

[dune73]

Status Summary The patch is aimed at the error-log and fixes a bug, where apache did not get the correct information from ModSec and some fields in the default apache ErrorLogFormat were thus empty. They are now filled. Because of this, there is a duplication of the client ip field, which is now present in the apache-part of the errorlog line and also in the modsecurity-part of the errorlog line. Attempts to fix this did not succeed during the test phase and 2.9.1 was thus released with this duplication.

While testing, it was also discovered that there is an additional line in the "H"-Parts of the Audit-Log and this line has some tags of the strformat string not replaced with the values (-> %s and the like). We could prove that this misbehaviour has been in the Audit-Log for a long time. What is new is the additional log line.

So we believe this is save for consumption, but of course, nobody can guarantee you that. And depending on the consumer it could fail - at least in theory.

If you are unsure, I suggest you pick up on one of the audit log examples above and fill it into the consumer in question. Then you should know.

Sorry for the inconvenience. This is not what I had in mind, when I filed the pull request (after testing it in production for a few months).