Revision as of 11:11, 1 August 2011

What is the audit log?

When modsecurity detects an event has occurred that it has been instructed to log, it will generate an audit log entry, and if properly configured an audit log event file. The audit log event file is the most useful piece of information the system will collect, so its vital modsecurity be setup correctly to capture this. Apache error logs, and the audit log itself are not particularly useful when trying to determine why an event has been captured.

If you are using ASL, then this is already setup for you and you can simply use the ASL gui to view the event. This article will focus on the audit log event details, and not on setting up modsecurity correctly.

Viewing events

In ASL simply click on the event from the "Security events" window, which will open the Event Detail window. The following is a screenshot of an example event.

Each part of the event is presented in multiple sections, each in different format, and separator begins with a "--".

Here is an example event, the section that follows this will explain what each section is and how to read these sections.

--5f3acc73-A--
[26/Jul/2011:11:45:49 +0700] Ti5GfNJW71wAAC63D4YAAABU 1.2.3.4 12446 5.6.7.8 80

--5f3acc73-B--
POST /newthread.php?do=postthread&f=8 HTTP/1.1
Host: www.example.com
User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:2.0.1) Gecko/20100101 Firefox/4.0.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us
Accept-Encoding: gzip, deflate
Accept-Charset: UTF-8,*
Keep-Alive: 115
Connection: keep-alive
Referer: http://www.example.com/newthread.php?do=newthread&f=8
Cookie: some cookie
Content-Type: application/x-www-form-urlencoded
Content-Length: 24390


--5f3acc73-C--
subject=some subject&message=link to a site thats banned such as http://www.example.com

--5f3acc73-F--
HTTP/1.1 403 Forbidden
Content-Length: 278
Keep-Alive: timeout=15, max=100
Connection: Keep-Alive
Content-Type: text/html; charset=iso-8859-1


--5f3acc73-H--
Message: [file "/etc/httpd/modsecurity.d/30_asl_antispam.conf"] [line "52"]
 [id "300001"] [rev "23"] [msg "Atomicorp.com WAF Rules: Blacklist Spam Domain"] 
[data ""] [severity "CRITICAL"] Access denied with code 403 (phase 2). 
Matched phrase "www.example.com" at ARGS:message.
Action: Intercepted (phase 2)
Apache-Handler: php5-script
Stopwatch: 1311655548998047 492700 (405774* 492191 -)
WAF: ModSecurity for Apache/2.5.13 ( http://www.modsecurity.org/); 201107251315.
Server: Apache/2.2.18 (CentOS)

Audit log sections

Section A - The audit log header

This section, the audit log header, contains only one line, with the following information on it:

• Timestamp
• Unique transaction ID
• Source IP address (IPv4 or IPv6)
• Source port
• Destination IP address (IPv4 or IPv6)
• Destination port

In the example above, this looks like this:

[26/Jul/2011:11:45:49 +0700] Ti5GfNJW71wAAC63D4YAAABU 1.2.3.4 12446 5.6.7.8 80

Section B - request headers

The request headers part contains the request line and the request headers. The information present in this part will not be identical to that sent by the client responsible for the transaction. ModSecurity does not have access to the raw data; it sees what Apache itself sees. While the end result may be identical to the raw request, differences are possible in some areas:

• If any of the fields are NUL-terminated, Apache will only see the content prior to the NUL.
• Headers that span multiple lines (feature known as header folding) will be collapsed into a single line.
• Multiple headers with the same name will be combined into a single header (as allowed by the HTTP RFC).

From the example above, this looks like this:

--5f3acc73-B--
POST /newthread.php?do=postthread&f=8 HTTP/1.1
Host: www.example.com
User-Agent: Mozilla/5.0 (Windows NT 5.1; rv:2.0.1) Gecko/20100101 Firefox/4.0.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us
Accept-Encoding: gzip, deflate
Accept-Charset: UTF-8,*
Keep-Alive: 115
Connection: keep-alive
Referer: http://www.example.com/newthread.php?do=newthread&f=8
Cookie: some cookie
Content-Type: application/x-www-form-urlencoded
Content-Length: 24390

Section C - request body

This part contains the request body of the transaction:

From the example above, this looks like this: --5f3acc73-C-- subject=some subject&message=link to a site thats banned such as http://www.example.com

Section F - response headers

This part contains the actual response headers sent to the client. Since ModSecurity does not access the raw connection data, it constructs part F out of the internal Apache data structures that hold the response headers.

Some headers (the Date and Server response headers) are generated just before they are sent and ModSecurity is not able to record those.

From the example above, this looks like this:

--5f3acc73-F-- HTTP/1.1 403 Forbidden Content-Length: 278 Keep-Alive: timeout=15, max=100 Connection: Keep-Alive Content-Type: text/html; charset=iso-8859-1

Section H - audit log trailer

This is the most important of the audit log entry for determining what rule triggered, and why it triggered. Again the example:

--5f3acc73-H-- Message: [file "/etc/httpd/modsecurity.d/30_asl_antispam.conf"] [line "52"] [id "300001"] [rev "23"] [msg "Atomicorp.com WAF Rules: Blacklist Spam Domain"] [data ""] [severity "CRITICAL"] Access denied with code 403 (phase 2). Matched phrase "www.example.com" at ARGS:message. Action: Intercepted (phase 2) Apache-Handler: php5-script Stopwatch: 1311655548998047 492700 (405774* 492191 -) WAF: ModSecurity for Apache/2.5.13 ( http://www.modsecurity.org/); 201107251315. Server: Apache/2.2.18 (CentOS)

ASL will summarize most of this in the event detail window. If you need to look at the specific details of the event, they are presented below the summary in the ASL gui.

This section is broken into nine parts, each one provides information about why the event was triggered.

The first part tells what rule file triggered this event, in the example above that is this section:

[file "/etc/httpd/modsecurity.d/30_asl_antispam.conf"]

The second part tells what line in the rule file the rule starts on, and that element looks like this:

[line "52"]

The third element tells you what rule was triggered, in this example "300001":

[id "300001"]

The fourth element tells you what revision this rule is, in the example its "23":

[rev "23"]

The fifth element contains special data for debugging purposes, such as specific payload or information the developers need. This field is not always used. In this example, it is not used:

[data ""]

The sixth field defines the logging severity of this event, this is not used by modsecurity but is provided for external tools to utilize for prioritizing. In the example, that field looks like this:

[severity "CRITICAL"]

And the seventh section is not bounded, and describes what action occurred and what in phase it occurred, in this example that looks like this:

Access denied with code 403 (phase 2).

And the final section provides information about what triggered the event, in this example that looks like this:

Matched phrase "www.example.com" at ARGS:message.