Auditlog is not output #2220

nakacya · 2019-12-16T08:51:53Z

http: //localhost/?param="><script>alert(1);</script>
http: //localhost/?union+select

Blocked when executing the above (normally so far)
・ It is recorded in error log.
・Not output to Auditlog.

Logs and dumps

Output of:

DebugLogs (level 9)
https://gist.github.com/nakacya/9614561b559cb04ac5d4edc35449621c
AuditLogs
no log
Error logs

2019/12/16 12:18:01 [error] 15769#15769: *1 [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `15' ) [file "/etc/nginx/modsecurity3/activated_rules/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "79"] [id "949110"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 15)"] [data ""] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "127.0.0.1"] [uri "/"] [unique_id "157649868155.730577"] [ref ""], client: 127.0.0.1, server: localhost, request: "GET /?param="><script>alert(1);</script> HTTP/1.1", host: "localhost"

If there is a crash, the core dump file.
None

Expected behavior

A clear and concise description of what you expected to happen.

Server (please complete the following information):

ModSecurity version (and connector): ModSecurity v3.0.3 (Linux) with nginx-connector v1.0.0
WebServer: nginx1.17.3
OS (and distro): amazon linux 2

Rule Set (please complete the following information):

Running any public or commercial rule set? [SpiderLabs public rules]
What is the version number? [e.g. Version 3.2.0]

Not all Auditlogs are out.
return code 200 is output normally

SecAuditEngine RelevantOnly
SecAuditLogRelevantStatus "^[0-9]+"
SecAuditLogParts ABCDEFGHIJKZ
SecAuditLog /var/log/modsecurity/modsec_audit.log
SecAuditLogType Concurrent
SecAuditLogStorageDir /var/log/modsecurity/es
SecAuditLogFormat JSON

400 series return code is also output in json, but the message part such as ruleid is missing

The text was updated successfully, but these errors were encountered:

zimmerle · 2019-12-16T12:55:21Z

can you please post how this "partial" JSON looks like?

nakacya · 2019-12-16T13:52:17Z

THX For reply

For example, this JSON is output but ruleid is not included.

{
  "transaction": {
    "client_ip": "xxx.xxx.xxx.xxx",
    "time_stamp": "Mon Dec 16 13:46:54 2019",
    "server_id": "f3cf3e49811aac12eb2fe60eec861eed40feb9af",
    "client_port": 53549,
    "host_ip": "172.30.1.86",
    "host_port": 80,
    "unique_id": "157650401449.074622",
    "request": {
      "method": "GET",
      "http_version": 1.1,
      "uri": "/wp-json/oembed/1.0/embed?=",
      "body": "",
      "headers": {
        "Host": "**.**.jp",
        "Connection": "keep-alive",
        "Cache-Control": "max-age=0",
        "DNT": "1",
        "User-Agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36",
        "Cookie": "wordpress_test_cookie=WP+Cookie+check; wordpress_logged_in_8626befbdd4025a3e929f4bffe6825ca=nakacya%7C1576299971%7CBpdVHllEtakd5vULPDOAFqr8yAsNOUqplrtDvWl9QOc%7C3f5920b03363c63257afc6683dc42fd124d378d3cf74e959761d9d33627bb114; wp-settings-time-1=1576127171",
        "Upgrade-Insecure-Requests": "1",
        "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3",
        "Accept-Encoding": "gzip, deflate",
        "Accept-Language": "ja,en-US;q=0.9,en;q=0.8"
      }
    },
    "response": {
      "body": "",
      "http_code": 400,
      "headers": {
        "Access-Control-Allow-Headers": "Authorization, Content-Type",
        "Link": "<http://**.**..jp/wp-json/>; rel=\"https://api.w.org/\"",
        "Content-Type": "application/json; charset=UTF-8",
        "Allow": "GET",
        "Connection": "keep-alive",
        "X-Content-Type-Options": "nosniff",
        "Access-Control-Expose-Headers": "X-WP-Total, X-WP-TotalPages",
        "Date": "Mon, 16 Dec 2019 13:46:54 GMT",
        "X-Robots-Tag": "noindex",
        "Server": "nginx",
        "Vary": "Origin"
      }
    },
    "producer": {
      "modsecurity": "ModSecurity v3.0.3 (Linux)",
      "connector": "ModSecurity-nginx v1.0.0",
      "secrules_engine": "Enabled",
      "components": [
        "OWASP_CRS/3.2.0\""
      ]
    },
    "messages": []
  }
}

martinhsv · 2019-12-16T20:40:45Z

Hi @nakacya ,

I'm not certain whether this is your issue, but there was a bug fix in October (d4dc3db ) that may be relevant. For that bug, the details that you note as missing were being omitted when the disruptive action was 'deny'.

If you're using 3.0.3 either from a repo package or from the 3.0.3-tagged github commit (from Nov. 1, 2018), you might have your logging issue fixed if you move up to at least 6395fe0

nakacya · 2019-12-17T00:27:01Z

THX forreply @martinhsv

I checked, but it seems that the corresponding correction has been completed.
I was in trouble ...

git show
commit 6624a18a4e7fd9881a7a9b435db3e481e8e986a5 (HEAD -> v3/master, origin/v3/master, origin/HEAD)


ModSecurity - v3.0.3-114-g6624a18a for Linux

 Mandatory dependencies
   + libInjection                                  ....v3.9.2-30-gbf234eb
   + SecLang tests                                 ....c8cf2c5

 Optional dependencies
   + GeoIP/MaxMind                                 ....found
      * (MaxMind) v1.2.0
         -lmaxminddb  , -DWITH_MAXMIND
   + LibCURL                                       ....found v7.61.1
      -lcurl,  -DWITH_CURL_SSLVERSION_TLSv1_2 -DWITH_CURL
   + YAJL                                          ....found v2.0.4
      -lyajl  , -DWITH_YAJL
   + LMDB                                          ....disabled
   + LibXML2                                       ....found v2.9.1
      -lxml2 -lz -lm -ldl, -I/usr/include/libxml2 -DWITH_LIBXML2
   + SSDEEP                                        ....not found
   + LUA                                           ....not found

 Other Options
   + Test Utilities                                ....enabled
   + SecDebugLog                                   ....enabled
   + afl fuzzer                                    ....disabled
   + library examples                              ....enabled
   + Building parser                               ....disabled
   + Treating pm operations as critical section    ....disabled

nakacya · 2019-12-17T01:43:37Z

Oh?
I tried accessing it with a browser.
Why is the content of auditlog being favicon.ico
Is it?

“xmlrpc.php?rsd=%00” should have been rejected by modsecurity ...

curl doesn't require a favicon, so why don't it appear in the auditlog?

[modsecuritylog]
2019/12/17 01:29:39 [error] 12446#12446: *1 [client xxx.xxx.xxx.xxx] ModSecurity: Access denied with code 403 (phase -1). Matched "Operator `Ge' with parameter `5' against variable `TX:ANOMALY_SCORE' (Value: `16' ) [file ""] [line "0"] [id "0"] [rev ""] [msg "Inbound Anomaly Score Exceeded (Total Score: 16)"] [data "Restricted header detected: accept-language"] [severity "2"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "172.30.1.86"] [uri "/xmlrpc.php"] [unique_id "1576546179"] [ref "o6,4o7,3v5,10o0,4v33,4o0,4v33,4t:lowercaseo0,10v56,10o0,10v56,10t:lowercaseo0,13v79,13o0,13v79,13t:lowercaseo0,3v104,3o0,3v104,3t:lowercaseo0,10v140,10o0,10v140,10t:lowercaseo0,6v473,6o0,6v473,6t:lowercaseo0,25v111,25o0,25v111,25t:lowercaseo0,6v274,6o0,6v274,6t:lowercaseo0,15v401,15o0,15v401,15t:lowercaseo0,15v432,15o0,15v432,15t:lowercase"], client: xxx.xxx.xxx.xxx, server: xxx.xxx.xxx.xxx.jp, request: "GET /xmlrpc.php?rsd=%00 HTTP/1.1", host: "xxx.xxx.xxx.xxx.jp

[auditlog]
xxx.xxx.xxx.xxx.jp xxx.xxx.xxx.xxx - [17/Dec/2019:01:29:39 +0000] "GET /favicon.ico HTTP/1.1" 200 0 http://xxx.xxx.xxx.xxx.jp/xmlrpc.php?rsd=%00 "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36" 1576546179 http://xxx.xxx.xxx.xxx.jp/xmlrpc.php?rsd=%00 /var/log/modsecurity/es/20191217/20191217-0129/20191217-012939-1576546179 0 1488.000000 md5:0f0dd73dcc81e942c0778d6e31b5c9d1

[JSON]
{
  "transaction": {
    "client_ip": "xxx.xxx.xxx.xxx",
    "time_stamp": "Tue Dec 17 01:29:39 2019",
    "server_id": "f3cf3e49811aac12eb2fe60eec861eed40feb9af",
    "client_port": 63996,
    "host_ip": "172.30.1.86",
    "host_port": 80,
    "unique_id": "1576546179",
    "request": {
      "method": "GET",
      "http_version": 1.1,
      "uri": "/favicon.ico",                  favicon.ico ?
      "body": "",
      "headers": {
        "Accept-Language": "ja,en-US;q=0.9,en;q=0.8",
        "Accept-Encoding": "gzip, deflate",
        "Cookie": "wordpress_test_cookie=WP+Cookie+check; wordpress_logged_in_8626befbdd4025a3e929f4bffe6825ca=nakacya%7C1576681028%7CWrIYDg4WSQcSksaZKClkmbQ0SGppMkOD0YGPPj8COsN%7C8a6b232e78e293b38d26d986e9df31012072917614c7c9a300530843c5720bc3; wp-settings-time-1=1576508468",
        "Referer": "http://xxx.xxx.xxx.xxx.jp/xmlrpc.php?rsd=%00",
        "Pragma": "no-cache",
        "Accept": "image/webp,image/apng,image/*,*/*;q=0.8",
        "Cache-Control": "no-cache",
        "DNT": "1",
        "User-Agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36",
        "Connection": "keep-alive",
        "Host": "xxx.xxx.xxx.xxx.jp"
      }
    },
    "response": {
      "body": "",
      "http_code": 200,                 Why return code 200?
      "headers": {
        "Server": "nginx",
        "Date": "Tue, 17 Dec 2019 01:29:39 GMT",
        "Content-Length": "43",
        "Expires": "Thu, 16 Jan 2020 01:29:39 GMT",
        "Content-Type": "image/gif",
        "Last-Modified": "Mon, 28 Sep 1970 06:00:00 GMT",
        "Connection": "keep-alive",
        "Cache-Control": "max-age=2592000"
      }
    },
    "producer": {
      "modsecurity": "ModSecurity v3.0.4 (Linux)",
      "connector": "ModSecurity-nginx v1.0.0",
      "secrules_engine": "Enabled",
      "components": [
        "OWASP_CRS/3.2.0\""
      ]
    },
    "messages": []
  }
}

martinhsv · 2019-12-17T03:34:04Z

Hi @nakacya ,

One thing I noticed that is a little unusual is your setting

SecAuditLogRelevantStatus "^[0-9]+"

This means you are telling ModSecurity to write to the audit log for transactions for any status code. E.g. even if the HTTP Status Code is 200, that is considered 'Relevant' because of your setting, so log writing occurs. But the "messages" portion of the log would be empty because ModSecurity has not populated it with anything because there is no information to convey.

A request for favicon.ico was likely sent by your browser (you can confirm this by using your browser's developer tools). The favicon.ico request did not trigger any ModSecurity detections. The return code for that particular transaction was 200, but the transaction was written to the audit log anyway -- again, with an empty "messages" portion because there was no detection information to include.

nakacya · 2019-12-17T04:26:05Z

THX Reply @martinhsv

I'm trying to change this setting now, but the audit log shows a return code 200.
In error log (modsecurity log), 403 is recorded normally, and 403 is also displayed in the page display, and there is no problem.

SecAuditEngine RelevantOnly
SecAuditLogRelevantStatus "^[4-5]+"

In the first place, /favicon.ico does not exist.

nakacya · 2019-12-17T04:48:27Z

THX Reply @martinhsv

I'm sorry I made a mistake reading.

When I checked with the developer tool, I got the following three requests.
/xmlrpc.php?rsd=%00
/content.min.css
/favicon.ico
And xmlrpc.php was rejected. (As planned)
Others were loaded normally (this is also normal)

I think
Shouldn't Auditlog be issued only for xmlrpc.php rejection in this case?

martinhsv · 2019-12-17T17:47:24Z

If requests for /content.min.ss and /favicon.ico return HTTP Status 200, then, based on those settings (SecAuditLogRelevantStatus "^[4-5]+"), there will be no audit log entry for those two requests.

However, logging is also controlled other ways, including at the individual rule level. For example you could intentionally set a rule to include 'log,pass' amongst its actions. And other rules that are triggered, but are not intended to block may require a specific 'nolog' or 'noauditlog' action to prevent writing to the audit log.

nakacya · 2019-12-17T23:57:56Z

When you get the following URL
http://xxx.xxx.xxx.jp/xmlrpc.php?rsd=%00%22

If requests for /content.min.ss and /favicon.ico return HTTP Status 200, then, based on those settings (SecAuditLogRelevantStatus "^ [4-5] +"), there will be no audit log entry for those two requests .

Yes, I understand this.
But why is there no audit log for rejected /xmlrpc.php?rsd=%00%22?

The error log (log) is output as follows.

[errorlog]
2019/12/17 23:33:53 [error] 14168 # 14168: * 3 [client xxx.xxx.xxx.xxx] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator` Ge 'with parameter ` 5 'against variable `TX: ANOMALY_SCORE' (Value:` 8 ') [file "/etc/nginx/modsecurity3/activated_rules/rules/REQUEST-949-BLOCKING-EVALUATION.conf"] [line "79"] [id " 949110 "] [rev" "] [msg" Inbound Anomaly Score Exceeded (Total Score: 8) "] [data" "] [severity" 2 "] [ver" "] [maturity" 0 "] [accuracy" 0 " ] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-generic"] [hostname "172.30.1.86"] [uri "/xmlrpc.php"] [unique_id "15766256332.509958"] [ref ""], client: xxx.xxx.xxx.xxx, server: xxx.xxx.xxx.xxxjp, request: "GET /xmlrpc.php?rsd=%00%22 HTTP / 1.1 ", host:" xxx.xxx.xxx.xxxjp "

In crs-setup.conf, it is described as follows.

SecDefaultAction "phase: 1, nolog, auditlog, pass"
SecDefaultAction "phase: 2, nolog, auditlog, pass"

id: 949110 is set as follows.

SecRule TX: ANOMALY_SCORE "@ge% {tx.inbound_anomaly_score_threshold}" \
    "id: 949110, \
    phase: 2, \
    deny, \
    t: none, \
    log, auditlog, \
    msg: 'Inbound Anomaly Score Exceeded (Total Score:% {TX.ANOMALY_SCORE})', \
    tag: 'application-multi', \
    tag: 'language-multi', \
    tag: 'platform-multi', \
    tag: 'attack-generic', \
    severity: 'CRITICAL', \
    setvar: 'tx.inbound_anomaly_score =% {tx.anomaly_score}' "

In the case of setting above, it should be set that “id: 949110 is output to log and audit log”.
However, it is output to log but nothing is output to the audit log.

However, I tried changing the settings in various ways, but the situation is as follows.
・ Nolog does not work (always output)
・Auditlog is not output normally

martinhsv · 2019-12-18T18:54:30Z

I'm sorry but I cannot reproduce what you are seeing. With current v3/master and the rule and configuration details that you have supplied above, I get content in the audit log including the "messages" section that specifies the rule id as 949110.

For that request (http://xxx.xxx.xxx.jp/xmlrpc.php?rsd=%00%22):

To clarify, when you say 'nothing is output to the audit log' do you mean that literally that no output at all is appearing in the audit log? If so, that's quite different from what has been discussed so far.

If there is some content going to the audit log, and it's just missing some details like the rule id ('949110'), is the messages section present but empty? ( E.g. "messages":[]}} )? Or is the messages section missing altogether?

martinhsv · 2020-01-03T19:30:12Z

Hi @nakacya ,

Although I wasn't able to reproduce what you were reporting, investigation related to your report did show a problem with the combination 'nolog,auditlog' that would affect output in some cases.

A fix for this may be available in v3/master soon-ish. But, in the meantime my suggestion to you would be to try changing your SecDefaultAction lines to be 'log,auditlog'.

nakacya · 2020-01-05T13:39:14Z

Hello @martinhsv,

I'm sorry to reply late at the end of Japan.
I understand the log.

When will you fix it?
I want to keep a schedule open if possible

martinhsv · 2020-01-07T22:30:25Z

Hi @nakacya ,

That fix for the 'nolog,auditlog' use case that I mentioned has been merged to v3/master.

Again, since I was not able to reproduce what you were reporting I cannot give assurance that that will fix your problem.

However, since you are using SecDefaultAction that includes 'nolog,auditlog', this newly-merged fix, might be of some help.

nakacya · 2020-01-10T02:57:45Z

Hi, @martinhsv

Today I got a new repository and tested it.
After all the result did not change.

Basically, isn't the auditlog output for a deny rule?
The content of the test is as follows: The test conforms to rule: 949110, but is not output to auditlog.

1) http://www.mydomain/?Union+select
2) http://host_IP/?Param=“><script>alert(1);</ script>

I changed log, \ of rule: 949110 to log, auditlog, \ but no auditlog is output.
If deny of rule: 949110 is changed to block, auditlog is output but it cannot be protected.

zimmerle · 2020-01-14T13:37:04Z

Hi @nakacya,

Can you create a minimalist ruleset to test such functionality?

nakacya · 2020-01-15T03:10:46Z

Hi @zimmerle

How simple rules are suitable?

http://www.mydomain.jp/admin


Deny & log & auditlog output
cat main.conf
Include "/etc/nginx/modsecurity3/modsecurity.conf"
## Basic test rule
SecRule REQUEST_URI \
        "@beginsWith /admin" \
        "phase:2,\
        t:lowercase,\
        id:2222,\
        deny,\
        log, \
        auditlog, \
        msg:'block admin'"

nginx error log
2020/01/15 02:36:29 [error] 29465#29465: *1 [client xxx.xxx.xxx.xxx] ModSecurity: Access denied with code 403 (phase 2). Matched "Operator `BeginsWith' with parameter `/admin' against variable `REQUEST_URI' (Value: `/admin' ) [file "/etc/nginx/modsecurity3/main.conf"] [line "5"] [id "2222"] [rev ""] [msg "block admin"] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "172.30.1.86"] [uri "/admin"] [unique_id "157905578990.186482"] [ref "o0,6v4,6t:lowercase"], client: xxx.xxx.xxx.xxx, server: www.example.jp, request: "GET /admin HTTP/1.1", host: "www.example.jp"

auditlog
None


block & log & auditlog output
cat main.conf
Include "/etc/nginx/modsecurity3/modsecurity.conf"
## Basic test rule
SecRule REQUEST_URI \
        "@beginsWith /admin" \
        "phase:2,\
        t:lowercase,\
        id:2222,\
        block,\
        log, \
        auditlog, \
        msg:'block admin'"


error log 
2020/01/15 02:37:48 [error] 29648#29648: *1 open() "/etc/nginx/html/admin" failed (2: No such file or directory), client: xxx.xxx.xxx.xxx, server: www.example.jp, request: "GET /admin HTTP/1.1", host: "www.example.jp"

auditlog
None

Ummmmmmm…….

nakacya · 2020-01-15T23:46:27Z

I repeated the test.

When SecRuleEngine DetectionOnly was selected, it was confirmed that auditlog was output even in the following cases.

When SecRuleEngine On was Not Output a auditlog

http://www.mydomain.jp/?param=“><script>alert(1);</script>
http://www.nakacya.jp/?union+select

config

cat main.conf
Include "/etc/nginx/modsecurity3/modsecurity.conf"
Include "/etc/nginx/modsecurity3/activated_rules/crs-setup.conf"
Include "/etc/nginx/modsecurity3/activated_rules/rules/*.conf"

victorhora · 2020-01-27T00:19:11Z

@nakacya see if victorhora/ModSecurity-nginx@ac3e8a9 solves your issue.

nakacya · 2020-01-27T02:10:12Z

@victorhora

Thank you for information!

I ran recompule.

git clone -b fix-auditlog-170 --depth=1 https://github.com/victorhora/ModSecurity-nginx.git
./nginx-build -d work -m module.conf -c config.conf
cd work/nginx/1.17.7/nginx-1.17.7
make install

We confirmed that auditlog was output without any problem.

victorhora mentioned this issue Jan 27, 2020

Fix audit_log not generated for disruptive actions owasp-modsecurity/ModSecurity-nginx#175

Closed

victorhora self-assigned this Jan 27, 2020

victorhora added 3.x Related to ModSecurity version 3.x bug It is a confirmed bug Platform - Nginx pr available labels Jan 27, 2020

nakacya closed this as completed Jan 27, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Auditlog is not output #2220

Auditlog is not output #2220

nakacya commented Dec 16, 2019 •

edited

Loading

zimmerle commented Dec 16, 2019

nakacya commented Dec 16, 2019

martinhsv commented Dec 16, 2019

nakacya commented Dec 17, 2019

nakacya commented Dec 17, 2019

martinhsv commented Dec 17, 2019

nakacya commented Dec 17, 2019

nakacya commented Dec 17, 2019

martinhsv commented Dec 17, 2019

nakacya commented Dec 17, 2019

martinhsv commented Dec 18, 2019

martinhsv commented Jan 3, 2020

nakacya commented Jan 5, 2020

martinhsv commented Jan 7, 2020

nakacya commented Jan 10, 2020

zimmerle commented Jan 14, 2020

nakacya commented Jan 15, 2020

nakacya commented Jan 15, 2020

victorhora commented Jan 27, 2020

nakacya commented Jan 27, 2020

Auditlog is not output #2220

Auditlog is not output #2220

Comments

nakacya commented Dec 16, 2019 • edited Loading

zimmerle commented Dec 16, 2019

nakacya commented Dec 16, 2019

martinhsv commented Dec 16, 2019

nakacya commented Dec 17, 2019

nakacya commented Dec 17, 2019

martinhsv commented Dec 17, 2019

nakacya commented Dec 17, 2019

nakacya commented Dec 17, 2019

martinhsv commented Dec 17, 2019

nakacya commented Dec 17, 2019

martinhsv commented Dec 18, 2019

martinhsv commented Jan 3, 2020

nakacya commented Jan 5, 2020

martinhsv commented Jan 7, 2020

nakacya commented Jan 10, 2020

zimmerle commented Jan 14, 2020

nakacya commented Jan 15, 2020

nakacya commented Jan 15, 2020

victorhora commented Jan 27, 2020

nakacya commented Jan 27, 2020

nakacya commented Dec 16, 2019 •

edited

Loading