Closed oleg9301 closed 6 years ago
Hi @oleg9301,
That's an interesting issue. The last commit we had on apache2_util.c was quite a while ago so my first guess is maybe with something on your compile / setup.
Could you share with us how you upgrade to 2.9.1? Clone from current master branch on Git? Release tarball? Debian package?
Also can you please provide the very first few lines of your error_log, just after restart your web server which shows the detailed version of Apache, APR, PCRE etc...?
I install 2.9.1 from debian repo(stretch)
dpkg -l libapache2-modsecurity
+++-==============-============-============-=================================
ii libapache2-mod 2.9.1-2 all Dummy transitional package
dpkg -l apache2
+++-=======================-================-================-================
ii apache2 2.4.25-3 amd64 Apache HTTP Server
error.log
[Wed Jun 21 06:25:31.000907 2017] [:notice] [pid 4425] ModSecurity: Loaded 29764 rules from: 'https://dashboard.modsecurity.org/rules/download/plain'.
[Wed Jun 21 06:25:31.001056 2017] [mpm_prefork:notice] [pid 4425] AH00163: Apache/2.4.25 (Debian) OpenSSL/1.0.2l configured -- resuming normal operations
[Wed Jun 21 06:25:31.001064 2017] [core:notice] [pid 4425] AH00094: Command line: '/usr/sbin/apache2'
[Wed Jun 21 06:25:31.001095 2017] [mpm_prefork:warn] [pid 4425] AH00167: long lost child came home! (pid 6341)
[Wed Jun 21 08:58:09.053829 2017] [mpm_prefork:notice] [pid 4425] AH00169: caught SIGTERM, shutting down
[Wed Jun 21 08:58:57.000512 2017] [:notice] [pid 11149] ModSecurity for Apache/2.9.1 (http://www.modsecurity.org/) configured.
[Wed Jun 21 08:58:57.000583 2017] [:notice] [pid 11149] ModSecurity: APR compiled version="1.5.2"; loaded version="1.5.2"
[Wed Jun 21 08:58:57.000591 2017] [:notice] [pid 11149] ModSecurity: PCRE compiled version="8.39 "; loaded version="8.39 2016-06-14"
[Wed Jun 21 08:58:57.000597 2017] [:notice] [pid 11149] ModSecurity: LUA compiled version="Lua 5.1"
[Wed Jun 21 08:58:57.000601 2017] [:notice] [pid 11149] ModSecurity: YAJL compiled version="2.1.0"
[Wed Jun 21 08:58:57.000606 2017] [:notice] [pid 11149] ModSecurity: LIBXML compiled version="2.9.4"
[Wed Jun 21 08:58:57.000611 2017] [:notice] [pid 11149] ModSecurity: Status engine is currently disabled, enable it by set SecStatusEngine to On.
@oleg9301 I see it on my side too. Here's a reproducer for others looking into this issue.
Dockerfile:
FROM debian
RUN apt-get update && apt-get -y install libapache2-modsecurity apache2
RUN mv /etc/modsecurity/modsecurity.conf-recommended /etc/modsecurity/modsecurity.conf
CMD ["-DFOREGROUND"]
ENTRYPOINT ["/sbin/apachectl"]
# docker build -t modsec-1468 .
# docker run -p 8000:80 --rm --name modsec-1468 -it modsec-1468
In another terminal, watch the audit log:
# docker exec -it modsec-1468 tail -f /var/log/apache2/modsec_audit.log | grep 'Apache-Error'
Finally, send a naughty request (I used the one shown in @oleg9301 's output)
# curl 'http://localhost:8000/search?utf8=\xe2\x9c\x93&q=..//..//../../12312312312312312312'
Back in the tail output:
# docker exec -it modsec-1468 tail -f /var/log/apache2/modsec_audit.log | grep 'Apache-Error'
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Interesting.
If use the module that comes with the package I get the same error:
root@debian:/var/log/apache2# tail -f /var/log/apache2/modsec_audit.log | grep 'Apache-Error'
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
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
But if I use a module from a build from master I don't see it:
root@debian:/var/log/apache2# tail -f /var/log/apache2/modsec_audit.log | grep 'Apache-Error'
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client ::1] ModSecurity: Warning. Pattern match "(?i)(?:\\\\\\\\x5c|(?:%(?:c(?:0%(?:[2aq]f|5c|9v)|1%(?:[19p]c|8s|af))|2(?:5(?:c(?:0%25af|1%259c)|2f|5c)|%46|f)|(?:(?:f(?:8%8)?0%8|e)0%80%a|bg%q)f|%3(?:2(?:%(?:%6|4)6|F)|5%%63)|u(?:221[56]|002f|EFC8|F025)|1u|5c)|0x(?:2f|5c)|\\\\\\\\/))(?:%(?:(?:f(?:(?:c%80|8)%8)?0%8 ..." at REQUEST_URI_RAW. [file "/usr/share/modsecurity-crs/rules/REQUEST-930-APPLICATION-ATTACK-LFI.conf"] [line "50"] [id "930100"] [rev "3"] [msg "Path Traversal Attack (/../)"] [data "Matched Data: /../ found within REQUEST_URI_RAW: /search?utf8=\\\\x5cxe2\\\\x5cx9c\\\\x5cx93&q=..//..//../../12312312312312312312"] [severity "CRITICAL"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "7"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-lfi"] [tag "OWASP_CRS/WEB_ATTACK/DIR_TRAVERSAL"] [hostname "localhost"] [uri "/search"] [unique_id "WUOh338AAQEAAXtfNSoAAAAC"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client ::1] ModSecurity: Warning. Matched phrase "../" at REQUEST_URI. [file "/usr/share/modsecurity-crs/rules/REQUEST-930-APPLICATION-ATTACK-LFI.conf"] [line "77"] [id "930110"] [rev "1"] [msg "Path Traversal Attack (/../)"] [data "Matched Data: ../ found within REQUEST_URI: /search?utf8=\\\\x5cxe2\\\\x5cx9c\\\\x5cx93&q=..//..//../../12312312312312312312"] [severity "CRITICAL"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "7"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-lfi"] [tag "OWASP_CRS/WEB_ATTACK/DIR_TRAVERSAL"] [hostname "localhost"] [uri "/search"] [unique_id "WUOh338AAQEAAXtfNSoAAAAC"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client ::1] ModSecurity: Warning. Matched phrase "../" at REQUEST_URI. [file "/usr/share/modsecurity-crs/rules/REQUEST-930-APPLICATION-ATTACK-LFI.conf"] [line "77"] [id "930110"] [rev "1"] [msg "Path Traversal Attack (/../)"] [data "Matched Data: ../ found within REQUEST_URI: /search?utf8=xe2x9cx93&q=..//..//../../12312312312312312312"] [severity "CRITICAL"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "7"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-lfi"] [tag "OWASP_CRS/WEB_ATTACK/DIR_TRAVERSAL"] [hostname "localhost"] [uri "/search"] [unique_id "WUOh338AAQEAAXtfNSoAAAAC"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client ::1] ModSecurity: Access denied with code 403 (phase 2). Operator GE matched 5 at TX:anomaly_score. [file "/usr/share/modsecurity-crs/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "57"] [id "949110"] [msg "Inbound Anomaly Score Exceeded (Total Score: 15)"] [severity "CRITICAL"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "localhost"] [uri "/search"] [unique_id "WUOh338AAQEAAXtfNSoAAAAC"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client ::1] ModSecurity: Warning. Operator GE matched 5 at TX:inbound_anomaly_score. [file "/usr/share/modsecurity-crs/rules/RESPONSE-980-CORRELATION.conf"] [line "73"] [id "980130"] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 15 - SQLI=0,XSS=0,RFI=0,LFI=15,RCE=0,PHPI=0,HTTP=0,SESS=0): Path Traversal Attack (/../)"] [tag "event-correlation"] [hostname "localhost"] [uri "/search"] [unique_id "WUOh338AAQEAAXtfNSoAAAAC"]
Will look more into it and get back once I know more.
Thanks for the update @oleg9301 and for the detailed report / reproduction steps @bostrt :)
Ok the problem here is that the Debian package is a bit "outdated".
So, there used to be an old bug in the the hook_error_log function. More specifically in this older code here:
if (info->format != NULL) em->message = apr_pstrdup(msr->mp, info->format);
The last argument on that attribution to em->message
doesn't seem right as info->format
contains the error message format but not the actual formatted error message so instead It should be apr_pstrdup(msr->mp, errstr)
.
I've tested dirty patching this bit straight on the source code used by package and the error message is not there anymore.
I would suggest @inittab to either apply patch #1216 or update the package to the latest master branch which has a number of fixes and improvements and should be stable for a 2.9.1-3 package until we have 2.9.2 released.
Hiya. I'll build an updated package and upload it to sid ASAP. Once it gets into testing I'll upload to backports.
I've noticed Alberto published new packages already:
https://launchpad.net/ubuntu/+source/modsecurity-apache/2.9.1-3
https://packages.debian.org/sid/i386/libapache2-mod-security2 (CHANGELOG)
Are you publishing other packages we should be aware of? I would like to know :)
Thank you @inittab! :)
Hi Victor. All my packages are uploaded to Debian's repositories. I'm also de maintainer of CRS. :-)
@victorhora @inittab is there any backport for the xenial for the version 2.9.1-3?
Hi, I'm sorry but I don't know about Ubuntu's backports.
I tried compiling v2/master branch but it does not fix this.
Can you elaborate more @rohanvakharia ?
I am facing the same issue as @-oleg9301 explained in above comments. As you mentioned that this issue is fixed in the latest patch-2.9.1-3 issued for debian. But there is no patch issued yet for Ubuntu Xeniel 16.04(LTS). So I request to patch the same to Ubuntu package maintainer (oerdnj) and parallely tried to compile the v2 master branch. I did successfully compiled the file but that didn't solved the issue. So I waiting for the oerdnj to release the patch.
Was this issue resolved? I get similar warnings when calling any Lua script, even the most basic. This is on Ubuntu 16.04 LTS and I'm used a compiled version of modsecurity (v2.9.2). For example:
--7a592842-H--
Message: Starting script execution
Message: Script execution finished
Message: Warning. Pattern match "GET" at REQUEST_METHOD. [file "/etc/modsecurity/modsecurity.conf"] [line "227"] [id "22"]
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Starting script execution \\n [hostname "localhost"] [uri "/"] [unique_id "WqnZvwqY10sAABQmegAAAAAA"]
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Script execution finished\\n [hostname "localhost"] [uri "/"] [unique_id "WqnZvwqY10sAABQmegAAAAAA"]
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Warning. Pattern match "GET" at REQUEST_METHOD. [file "/etc/modsecurity/modsecurity.conf"] [line "227"] [id "22"] [hostname "localhost"] [uri "/"] [unique_id "WqnZvwqY10sAABQmegAAAAAA"]
Stopwatch: 1521080767795968 2593 (- - -)
Stopwatch2: 1521080767795968 2593; combined=1998, p1=7, p2=1989, p3=0, p4=0, p5=1, sr=0, sw=1, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.9.2 (http://www.modsecurity.org/).
Server: Apache/2.4.18 (Ubuntu)
Engine-Mode: "DETECTION_ONLY"
and the lua script looks like this:
#!/usr/bin/lua
function main()
m.log(1,"Starting script execution \n")
m.log(1,"Script execution finished \n")
end
@ossie-git, I'm not sure if using m.log() is the best approach for "normal" logging. It might trigger debug messages and may be the reason why you're seeing "Apache-Error" messages when running Lua scripts.
Maybe you want to give it a try with a something like: return "Script execution finished";
as per the Lua script examples on the reference manual.
Alternatively you can also try using different log levels as log levels between 1 and 3 are the ones that will be logged to the error_log (as far as I can remember).
Thanks Victor. You were right on that using a different log level eliminated some of the Apache-Error lines but not all of them. I removed all rules and just had the following rule:
SecRule REQUEST_METHOD "GET" "phase:2,id:21,pass,exec:/tmp/test.lua"
which now looks like this:
#!/usr/bin/lua
function main()
m.log(4,"Starting script execution \n")
m.log(4,"Script execution finished \n")
end
I would then get:
--e12cb04a-H--
Message: Warning. Pattern match "GET" at REQUEST_METHOD. [file "/etc/modsecurity/modsecurity.conf"] [line "237"] [id "21"]
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Warning. Pattern match "GET" at REQUEST_METHOD. [file "/etc/modsecurity/modsecurity.conf"] [line "237"] [id "21"] [hostname "localhost"] [uri "/"] [unique_id "WqrOiwqY11cAAEDfxAIAAABA"]
Stopwatch: 1521143435645762 8104 (- - -)
Stopwatch2: 1521143435645762 8104; combined=2816, p1=434, p2=2165, p3=80, p4=44, p5=93, sr=0, sw=0, l=0, gc=0
Producer: ModSecurity for Apache/2.9.2 (http://www.modsecurity.org/).
Server: Apache/2.4.18 (Ubuntu)
Engine-Mode: "DETECTION_ONLY"
So it removed the following two lines but kept one:
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Starting script execution \\n [hostname "localhost"] [uri "/"] [unique_id "WqrOcAqY11cAAEB3NqAAAABA"]
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Script execution finished \\n [hostname "localhost"] [uri "/"] [unique_id "WqrOcAqY11cAAEB3NqAAAABA"]
But even if I disable the Lua rule entirely and just have a single rule that is not Lua-related and looks like this:
SecRule ARGS "@contains MY_UNIQUE_TEST_STRING" \
"id:2002,phase:2,deny,status:503,log"
I still end up with Apache-Error
--3bceb074-H--
Message: Warning. String match "MY_UNIQUE_TEST_STRING" at ARGS:test. [file "/etc/modsecurity/modsecurity.conf"] [line "235"] [id "2002"]
Apache-Error: [file "apache2_util.c"] [line 273] [level 3] [client 127.0.0.1] ModSecurity: Warning. String match "MY_UNIQUE_TEST_STRING" at ARGS:test. [file "/etc/modsecurity/modsecurity.conf"] [line "235"] [id "2002"] [hostname "localhost"] [uri "/"] [unique_id "WqrN9QqY11cAAEAMNwgAAAAA"]
Stopwatch: 1521143285279978 6148 (- - -)
Stopwatch2: 1521143285279978 6148; combined=1902, p1=433, p2=1303, p3=24, p4=24, p5=118, sr=0, sw=0, l=0, gc=0 Producer: ModSecurity for Apache/2.9.2 (http://www.modsecurity.org/).
Server: Apache/2.4.18 (Ubuntu) Engine-Mode: "DETECTION_ONLY"
Any ideas? Thanks.
@ossie-git Maybe your disruptive action leading to a 5xx HTTP error? Try changing the status to a "403" and see if it makes a difference.
Tried it with 403 but it is still the same. The lua rule also triggers one even when it has no associated disruptive action as well
Hi @ossie-git,
I was reviewing the code and specs I remembered that the "Apache-Error" message on the auditlogs is actually normal behaviour.
If you look at msc_logging.c you can see that the Apache-Error header is always added as part of Audit Log every time a log entry is sent to Apache error_log.
This is also written on to the ModSecurity Data Formats reference "The Apache-Error header contains Apache error log messages observed by ModSecurity, excluding those sent by ModSecurity itself"
So if you really don't want the "Apache-Error" message showing on your audit logs you can either omit the "H" from the SecAuditLogParts (you might loose other information from the audit log as well) or maybe omit this in the code, but honestly the Apache-Error message is harmless and you can safely ignore it if you're not interested in it.
Keeping this one closed as it's not an issue.
Great. Thank you for the clarification.
Hi @victorhora,
I'm seeing this duplication of ModSecurity Messages: and the exact same entry in Apache-Error: lines in my H blocks on CentOS7 using ModSec 2.9.2, but I wasn't seeing this on CentOS6 using ModSec 2.9.1. Not sure why the difference. However, I would think we'd want to eliminate this duplicate logging as it wastes logging space.
I was reading: https://github.com/SpiderLabs/ModSecurity/wiki/ModSecurity-2-Data-Formats#Audit_Log_Header_code_classliteralAcode which states: "The Apache-Error header contains Apache error log messages observed by ModSecurity, excluding those sent by ModSecurity itself."
So, this documentation says that the messages sent by ModSecurity itself SHOULD be excluded (at least that is how I read it). And I would prefer it that way. Can you reopen this issue and eliminate the duplication of such messages in the H block? In both 2.9.x and 3.x?
@davewichers the messages that get sent to the Apache error log will also be shown in the AuditLog. (see msc_logging.c)
ModSecurity disruptive actions (e.g. deny) will normally trigger an event/entry on Apache error_log. Non-disruptive requests are not logged to the error_log, hence why there's no "Apache-Error" entry on the audit_log for these requests.
This behaviour can also be modified by changing Apache's LogLevel directive from "warn" to "crit" for instance.
It's still not clear if this is really a bug, a feature or misconfiguration and it's important to figure out before we can reopen the issue and focus developer's time to work on it.
So can you please point exactly which version of ModSecurity this behaviour has changed? Preferably from this Git repository (i.e. commit #abc / release #2.9.Z) as RPM/DEB packages tend to apply patches/changes independently making it much harder for us to track changes.
This will help us identifying a possible code change that could accidentally cause a different behaviour (assuming it's not actually a feature added on purpose).
Thanks!
I noticed this change when I switched from ModSecurity 2.9.1 on CentOS 6 with httpd 2.2.15-60 to ModSecurity 2.9.2 on CentOS 7 with httpd 2.4.6-67. I'm using ModSecurity in log mod only so I'm not denying anything. That's all the info I have at this time to help you try to track down the cause of this behavior change. And I have the LogLevels for both Apache and ModSecurity the same on both systems.
Hello Guys!
I install crs from github and update debian from 8 to 9. I have next software version:
And after update(ModSecurity 2.8.0 -> ModSecurity 2.9.1) I see next string in every ModSecurity log line.
audit.log