 > ModSecurity Handbook: Getting Started: Chapter 4. Logging |  |
> ModSecurity Handbook: Getting Started: Chapter 4. Logging | |
This section covers the logging capabilities of ModSecurity in detail. Logging is a big part of what ModSecurity does, so it will not surprise you to learn that there are extensive facilities available for your use.
The debug log is going to be your primary troubleshooting tool, especially initially, while you’re learning how ModSecurity works. You are likely to spend a lot of time with the debug log cranked up to level 9, observing why certain things work the way they do. There are two debug log directives, as you can see in Table 4.1, “Debug log directives”.
Table 4.1. Debug log directives
| Directive | Description |
|---|---|
SecDebugLog
| Path to the debug log file |
SecDebugLogLevel
| Debug log level |
In theory, there are 10 debug log levels, but not all are used. You’ll find the ones that are in Table 4.2, “Debug log levels”. Messages with levels 1–3 are designed to be meaningful, and are copied to the Apache’s error log. The higher-level messages are there mostly for troubleshooting and debugging.
Table 4.2. Debug log levels
| Debug log level | Description |
|---|---|
| 0 | No logging |
| 1 | Errors (e.g., fatal processing errors, blocked transactions) |
| 2 | Warnings (e.g., non-blocking rule matches) |
| 3 | Notices (e.g., non-fatal processing errors) |
| 4 | Informational |
| 5 | Detailed |
| 9 | Everything! |
You will want to keep the debug log level in production low (either at 3 if you want a copy of all messages in the debug log, or at 0 if you’re happy with having them only in the error log). This is because you can expect in excess of 50 debug log messages (each message is an I/O operation) and at least 7 KB of data for an average transaction. Logging all that for every single transaction consumes a lot of resources.
This is what a single debug log line looks like:
[18/Aug/2009:08:18:08 +0100] [192.168.3.111/sid#80f4e40][rid#81d0588][/index.html]↩ [4] Initialising transaction (txid SopVsH8AAAEAAE8-NB4AAAAD).
The line starts with metadata that is often longer than the message itself: the time, client’s IP address, internal server ID, internal request ID, request URI, and finally, the debug log level. The rest of the line is occupied by the message, which is essentially free-form. You will find many examples of debug log messages throughout this guide, which I’ve used to document how ModSecurity works.
There’s another reason for avoiding extensive debug logging in production, and that’s simply that it’s very difficult. There’s usually so much data that it sometimes takes you ages to find the messages pertaining to the transaction you wish to investigate. In spite of the difficulties, you may occasionally need to debug in production because you can’t reproduce a problem elsewhere.
ModSecurity 2.5 extended the audit logging functionality by being able to record in the audit log all the rules that matched. This feature is very helpful, as it minimizes the need for debugging in production, but it still can’t tell you why some rules didn’t match.
One way to make debugging easier is to keep debug logging disabled by default and
enable it only for the part of the site that you wish to debug. You can do this by
overriding the default configuration using the <Location>
context directive. While you’re doing that, it may be a good idea to specify a
different debug log file altogether. That way you’ll keep main debug log file free
of your tests.
<Location /myapp/>
SecDebugLogLevel 9
SecDebugLog /opt/modsecurity/var/log/troubleshooting.log
</Location>This approach, although handy, still does not guarantee that the volume of
information in the debug log will be manageable. What you really want is to enable
debug logging for the requests you send. ModSecurity provides a solution for this by
allowing a debug log level to be changed at runtime, on a per-request basis. This is
done using the special ctl action that allows some of the
configuration to be updated at runtime.
All you need to do is somehow uniquely identify yourself. In some circumstances, observing the IP address will be sufficient:
SecRule REMOTE_ADDR "@streq 192.168.1.1" \
phase:1,nolog,pass,ctl:debugLogLevel=9Using your IP address won’t work in the cases when you’re hidden by a NAT of some
sort, and share an IP address with a bunch of other users. One straightforward
approach is to modify your browser settings to put a unique identifier in your
User-Agent request header. (How exactly that is done depends
on the browser you are using. In Firefox, for example, you can add a
general.useragent.override setting to your configuration, or use one of the many
extensions specifically designed for this purpose.)
SecRule REQUEST_HEADERS:User-Agent YOUR_UNIQUE_ID \
phase:1,nolog,pass,ctl:debugLogLevel=9This approach, although easy, has a drawback: all your requests will cause an increase in debug logging. You may think of an application in terms of dynamic pages, but extensive debug logging will be enabled for every single embedded object, too. Also, if you’re dealing with an application that you’re using frequently, you may want to avoid excessive logging.
The most accurate way of dynamically enabling detailed debug logging is to
manually indicate, to ModSecurity, the exact requests on which you want it to
increase logging. You can do this by modifying your User-Agent
string on request-by-request basis, using one of the tools that support request
interception and modification. (The Tamper Data extension does that for Firefox.)
Armed with such a tool, you submit your requests in your browser, modify them in the
tool, and then allow them through modified. It’s a bit involved, but a time-saver
overall. And, while you are at it, it is a good idea to make your identifiers
similar enough for your rule to always detect them, but different enough to allow
you to use a search function to quickly find the exact request in a file with
thousands.
It is a little-known fact that I originally started to work on ModSecurity because I was frustrated with not being able to log full HTTP transaction data. The audit log, which does just that, was one of the first features implemented.
Table 4.3. Audit log directives
| Directive | Description |
|---|---|
SecAuditEngine
| Controls the audit log engine; possible values On,
Off, or RelevantOnly |
SecAuditLog
| Path to an audit log file |
SecAuditLog2
| Path to another audit log file (copy) |
SecAuditLogParts
| Specifies which part of a transaction will be logged |
SecAuditLogRelevantStatus
| Specifies which response statuses will be considered relevant |
SecAuditLogStorageDir
| Path there concurrent audit log files will be stored |
SecAuditLogType
| Specifies the type of audit log to use: Serial or
Concurrent |
A typical audit log entry (short, GET request without a body and no logging of the response body) consumes around 1.3 KB. Requests with bodies will increase the amount of data that needs to be logged, as well as the logging of response bodies.
Logically, each audit log entry is a single file. When serial audit logging is used, all entries will be placed within one file, but with concurrent audit logging, one file per entry is used. Looking at a single audit log entry, you’ll find that it consists of multiple independent segments (parts):
--6b253045-A-- ... --6b253045-B-- ... --6b253045-C-- ... --6b253045-F-- ... --6b253045-E-- ... --6b253045-H-- ... --6b253045-Z--
A segment begins with a boundary and ends when the next segment begins. The only
exception is the terminating segment (Z), which consists only of the
boundary. The idea behind the use of multiple segments is to allow each audit log entry
to contain potentially different information. Only the parts A and
Z are mandatory; the use of the other parts is controlled with
the SecAuditLogParts directive. Table 4.4, “Audit log parts”contains the list of all audit log parts, along with a description of their
purpose.
Table 4.4. Audit log parts
| Part letter | Description |
|---|---|
A
| Audit log header (mandatory) |
B
| Request headers |
C
| Request body |
D
| Reserved |
E
| Response body |
F
| Response headers |
G
| Reserved |
H
| Audit log trailer, which contains additional data |
I
| Compact request body alternative (to part C),
which excludes files |
J
| Information on uploaded files (available as of version 2.6.0) |
K
| Contains a list of all rules that matched for the transaction |
Z
| Final boundary (mandatory) |
Every audit log entry begins with part A, which contains the
basic information about the transaction: time, unique ID, source IP address, source
port, destination IP address, and destination port:
--6b253045-A-- [18/Aug/2009:08:25:15 +0100] SopXW38EAAE9YbLQ 192.168.3.1 2387 192.168.3.111 8080
Part B contains the request headers and nothing else:
--6b253045-B-- POST /index.html?a=test HTTP/1.1 Host: 192.168.3.111:8080 User-Agent: Mozilla/5.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: en-us,en;q=0.5 Accept-Encoding: gzip,deflate Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive Referer: http://192.168.3.111:8080/index.html?a=test Content-Type: application/x-www-form-urlencoded Content-Length: 6
Part C contains the raw request body, typically that of a
POST request:
--6b253045-C-- b=test
Part F contains the response headers:
--6b253045-F-- HTTP/1.1 200 OK Last-Modified: Tue, 18 Aug 2009 07:17:44 GMT ETag: "6eccf-99-4716550995f20" Accept-Ranges: bytes Content-Length: 159 Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Content-Type: text/html
Part E contains the response body:
--6b253045-E-- <html><body><h1>It works!</h1></body></html> <form action="index.html?a=test" method="POST"> <textarea name="b">test</textarea> <input type=submit> </form>
The final part, H, contains additional transaction
information.
--6b253045-H-- Stopwatch: 1250580315933960 1902 (551* 580 978) Response-Body-Transformed: Dechunked Producer: ModSecurity for Apache/2.5.9 (http://www.modsecurity.org/). Server: Apache/2.2.11 (Unix) DAV/2
Part K contains a list of rules that matched in a transaction.
It is not unusual for this part to be empty, but if you have a complex rule set, it
may show quite a few rules. Audit logs that record transactions on which there were
warnings, or those that were blocked, will contain at least one rule here. In this
example you’ll find a rule that emits a warning on every request:
--6b253045-K-- SecAction "phase:2,auditlog,log,pass,msg:'Matching test'"
Every audit log file ends with the terminating boundary, which is part
Z:
--6b253045-Z--
Initially, ModSecurity supported only the serial audit logging format. Concurrent logging was introduced to address two issues:
Serial logging is only adequate for moderate use, because only one audit log entry can be written at any one time. Serial logging is fast (logs are written at the end of every transaction, all in one go) but it does not scale well. In the extreme, a web server performing full transaction logging practically processes only one request at any one time.
Real-time audit log centralization requires individual audit log entries to be deleted once they are dealt with, which is impossible to do when all alerts are stored in a single file.
Concurrent audit logging changes the operation of ModSecurity in two aspects. To
observe the changes, switch to concurrent logging without activating
mlogc by changing SecAuditLogType to
Concurrent (don’t forget to restart Apache).
First, as expected, each audit log entry will be stored in a separate file. The
files will not be created directly in the folder specified by
SecAuditLogStorageDir, but in an elaborate structure of
subfolders whose names will be constructed from the current date and time:
./20090822 ./20090822/20090822-1324 ./20090822/20090822-1324/20090822-132420-SojdH8AAQEAAAugAQAAAAAA ./20090822/20090822-1324/20090822-132420-SojdH8AAQEAAAugAQEAAAAA
The purpose of the scheme is to prevent too many files from being created within
one directory; many filesystems have limits that can be relatively quickly reached
on a busy web server. The first two parts in each filename are based on time
(YYYYMMDD and HHMMSS). The third parameter
is the unique transaction ID.
In addition to each entry getting its own file, the format of the main audit log file will change when concurrent logging is activated. The file that previously stored the entries themselves will now be used as a record of all generated audit log files.
192.168.3.130 192.168.3.1 - - [22/Aug/2009:13:24:20 +0100] "GET / HTTP/1.1" 200 ↩ 56 "-" "-" SojdH8AAQEAAAugAQAAAAAA "-" ↩ /20090822/20090822-1324/20090822-132420-SojdH8AAQEAAAugAQAAAAAA 0 1248 ↩ md5:8b097f4f880852e179e7b63b68a7fc92 192.168.3.130 192.168.3.1 - - [22/Aug/2009:13:24:20 +0100] "GET /favicon.ico ↩ HTTP/1.1" 404 267 "-" "-" SojdH8AAQEAAAugAQEAAAAA "-" ↩ /20090822/20090822-1324/20090822-132420-SojdH8AAQEAAAugAQEAAAAA 0 1226 ↩ md5:c76740f076a3cb759d62fb610ab39342
The index file is similar in principle to a web server access log. Each line describes one transaction, duplicating some of the information already available in audit log entries. The purpose of the index file is two-fold:
The first part, which duplicates some of the information available in audit logs, serves as a record of everything that you have recorded so that you can easily search through it.
The second part tells you where an audit log entry is stored (e.g.,
/20090822/20090822-1324/20090822-132420-SojdH8AAQEAAAugAQEAAAAA),
where it begins within that file (always zero, because this feature is not
used), how long it is, and gives you its MD5 hash (useful to verify
integrity).
When real-time audit log centralization is used, this information is not written to a file. Instead, it is written to a pipe, which means that it is sent directly to another process, which deals with the information immediately. You will see how that works in the next section.
ModSecurity comes with a tool called mlogc (short for ModSecurity
Log Collector), which can be used to transport audit logs in real time to a remote
logging server. This tool has the following characteristics:
The communication path between your ModSecurity sensors and the remote logging server is secured with SSL and authenticated using HTTP Basic Authentication.
Remote logging is implemented with multiple threads of execution, which allow for many alerts to be handled in parallel. Existing HTTP connections are reused.
An audit log entry will be deleted from the sensor only once its safe receipt is acknowledged by the logging server.
The mlogc tool maintains its own audit entry queue,
which has two benefits. First, if the logging server is not available the
entries will be preserved, and submitted once the server comes back online.
Second, mlogc controls the rate at which audit log
entries are submitted, meaning that a burst of activity on a sensor will not
result in an uncontrolled burst of activity on the remote logging
server.
Remote logging uses a simple but very effective protocol based on HTTP. You’ll find it documented in Chapter 20, Data Formats.
If you’ve followed my installation instructions, you will have
mlogc compiled and sitting in your bin/
folder. To proceed, you will need to configure it, then add it to the ModSecurity
configuration.
The mlogc configuration file is similar to that of Apache, only
simpler. First we need to tell mlogc where its “home” is, which
is where it will create its log files. Log files are very important, because—as it
is Apache that starts mlogc and ModSecurity that talks to it—we
never interact with mlogc directly. We’ll need to look in the log
files for clues in case of problems.
# Specify the folder where the logs will be created CollectorRoot /opt/modsecurity/var/log # Define what the log files will be called. You probably # won't ever change the names, but mlogc requires you # to define it. ErrorLog mlogc-error.log # The error log level is a number between 0 and 5, with # level 3 recommended for production (5 for troubleshooting). ErrorLogLevel 3 # Specify the names of the data files. Similar comment as # above: you won't want to change these, but they are required. TransactionLog mlogc-transaction.log QueuePath mlogc-queue.log LockFile mlogc.lck
Then we tell it where to find audit log entries. The value given to
LogStorageDir should be the same as the one you provided to
ModSecurity’s SecAuditLogStorageDir:
# Where are the audit log entries created by ModSecurity? LogStorageDir /opt/modsecurity/var/audit
Next, we need to tell mlogc where to submit the audit log
entries. We identify a remote server with a URL and credentials:
# Remote logging server details. ConsoleURI "https://REMOTE_ADDRESS:8888/rpc/auditLogReceiver" SensorUsername "USERNAME" SensorPassword "PASSWORD"
The remaining configuration directives aren’t required, but it’s always a good idea to explicitly configure your programs, rather than let them use their defaults:
# How many parallel connections to use to talk to the server, # and how much to wait (in milliseconds) between submissions. # These two directives are used to control the rate at which # audit log entries are submitted. MaxConnections 10 TransactionDelay 50 # How many entries is a single thread allowed to process # before it must shut down. MaxWorkerRequests 1000 # How long to wait at startup before really starting. StartupDelay 5000 # Checkpoints are periods when the entries from the transaction # log (which is written to sequentially) are consolidated with # the entries in the main queue. CheckpointInterval 15 # Back-off time after goes away or responds with a fatal error. ServerErrorTimeout 60
You will need to make two changes to your default configuration. First you need to
switch to concurrent audit logging, because that’s the only way
mlogc can work:
SecAuditLogType Concurrent
Next you need to activate mlogc, which is done using the
piped logging feature of Apache:
SecAuditLog "|/opt/modsecurity/bin/mlogc /opt/modsecurity/etc/mlogc.conf"
The pipe character at the beginning of the line tells Apache to treat what follows
as a command line. As a result, whenever you start Apache from now on, it will start
a copy of mlogc in turn, and keep it running in parallel,
leaving a one-way communication channel that will be used by ModSecurity to inform
mlogc of every new audit log entry it creates.
Your complete configuration should look like this now:
SecAuditEngine RelevantOnly SecAuditLogRelevantStatus ^5 SecAuditLogParts ABDEFHIJKZ SecAuditLogType Concurrent SecAuditLog "|/opt/modsecurity/bin/mlogc /opt/modsecurity/etc/mlogc.conf" SecAuditLogStorageDir /opt/modsecurity/var/audit/
If you restart Apache now, you should see mlogc
running:
USER PID COMMAND root 11845 /usr/sbin/apache2 -k start root 11846 /opt/modsecurity/bin/mlogc /opt/modsecurity/etc/mlogc.conf apache 11847 /usr/sbin/apache2 -k start apache 11848 /usr/sbin/apache2 -k start apache 11849 /usr/sbin/apache2 -k start apache 11850 /usr/sbin/apache2 -k start apache 11851 /usr/sbin/apache2 -k start
If you go to the log/ folder, you should see two new log
files:
dev:/opt/modsecurity/var/log# l total 1684 drwx------ 2 root root 4096 2009-08-20 10:31 . drwxr-x--- 7 root apache 4096 2009-08-18 20:01 .. -rw-r----- 1 root root 926530 2009-08-20 08:09 audit.log -rw-r----- 1 root root 771903 2009-08-20 08:09 debug.log -rw-r--r-- 1 root root 696 2009-08-20 10:33 mlogc-error.log -rw-r--r-- 1 root root 0 2009-08-20 10:31 mlogc-transaction.log
If you look at the mlogc-error.log file, there will be signs
of minimal activity (the timestamps from the beginning of every line were removed
for clarity):
[3] [11893/0] Configuring ModSecurity Audit Log Collector 2.5.10-dev2. [3] [11893/0] Delaying execution for 5000ms. [3] [11895/0] Configuring ModSecurity Audit Log Collector 2.5.10-dev2. [3] [11895/0] Delaying execution for 5000ms. [3] [11893/0] Queue file not found. New one will be created. [3] [11893/0] Caught SIGTERM, shutting down. [3] [11893/0] ModSecurity Audit Log Collector 2.5.10-dev2 terminating normally. [3] [11895/0] Queue file not found. New one will be created.
It is normal for two copies of mlogc to have run, because
that’s how Apache treats all piped logging programs. It starts two (one while it’s
checking configuration), but leaves only one running. The second token on every line
in the example is the combination of process ID and thread ID. Thus you can see how
there are two processes running at the same time (PID 11893 and PID 11895). Because
only one program can handle the data files, mlogc is designed
to wait for a while before it does anything. Basically, if it still lives after the
delay, that means it’s the copy that’s meant to do something.
What happens if you make an error in the configuration file, which is preventing
mlogc from working properly? As previously discussed,
mlogc can’t just respond to you on the command line, so it
will do the only thing it can. It will report the problem and shut down. (Don’t be
surprised if Apache continues with attempts to start it. That’s what Apache does
with piped logging programs.)
If you make a mistake in defining the error log, you may actually get an error
message in response to the attempt to start Apache. Following is the error message
you’d get if you left ErrorLog undefined:
dev:/opt/modsecurity/etc# apache2ctl start [1] [12026/0] Failed to open the error log (null): Bad address [3] [12026/0] ModSecurity Audit Log Collector 2.5.10-dev2 terminating with error 1
If mlogc managed to open its error log, it will do the
expected and write all error messages there. For example:
[1] [11985/0] QueuePath not defined in the configuration file. [3] [11985/0] ModSecurity Audit Log Collector 2.5.10-dev2 terminating with error 1
At this point, it is a good idea to delete the serial audit log file
audit.log, or store it elsewhere. Having switched to
concurrent logging, that file won’t be updated anymore and it will only confuse
you.
Assuming default logging configuration (level 3), a single audit log entry handled
by mlogc will produce one line in the log file:
[3] [2435/693078] Entry completed (0.080 seconds, 9927 bytes): ↩ SsHOykMXI18AAAmnIgAAAABC
That’s basically all you need to know—that an entry has been safely transmitted
to the intended destination. The status codes 200 and 409 are taken to mean that an
entry has been successfully processed. The response code 200 indicates that there
were no problems with the entry; the response code 409 indicates that the entry is
faulty, but that it has been accepted by the server (and that
mlogc should delete it and move on).
You will get more information when something gets wrong, of course. For example, you will see the following message whenever your logging server goes down:
[2] [2435/693078] Flagging server as errored after failure to submit entry ↩ SsHPN0MXI18AAAmLHucAAAAG (cURL code 7): couldn't connect to host
The message will appear on the first failed delivery, and then once every minute
until the server becomes operational. This is because mlogc will
shut down its operation for a short period whenever something unusual happens with
the server. Only one thread of operation will continue to work to probe the server,
with processing returning to full speed once the server recovers. You’ll get the
following information in the log:
[3] [2435/693078] Clearing the server error flag after successful entry ↩ submission: SsHPN0MXI18AAAmLHucAAAAG [3] [2435/693078] Entry completed (0.684 seconds, 9927 bytes): ↩ SsHPN0MXI18AAAmLHucAAAAG
Going back to the error message, the first part tells you that there’s a problem with the server; the second part tells you what the problem is. In the previous case, the problem was “couldn’t connect to host”, which means the server is down.
Table 4.5. Common remote logging problems
| Error message | Description |
|---|---|
| couldn’t connect to host | The server could not be reached. It probably means that the server itself is down, but it could also indicate a network issue. You can investigate the cURL return code to determine the exact cause of the problem. |
| Possible SSL negotiation error | Most commonly, this message will mean that you configured
mlogc to submit over plain-text, but the
remote server uses SSL. Make sure the ConsoleURI
parameter starts with “https://”. |
| Unauthorized | The credentials are incorrect. Check the
SensorUsername and
SensorPassword parameters. |
| For input string: “0, 0” | A remote server can indicate an internal error using any response
status code other than 200 and 409, but such errors are treated as
transient. ModSecurity Community Console has a long-standing problem
where it responds with a 500 code to an audit log entry that is
invalid in some way. The use of the 500 response code makes
mlogc pause and attempt to deliver again,
only to see the Console fail again. The process continues
indefinitely and the only solution at the moment is to track down
the offending audit log entry on the sensor and manually delete
it. |
If you still can’t resolve the problem, I suggest that you increase the
mlogc error log level from 3 (NOTICE) to 5
(DEBUG2), restart Apache (graceful will do), and try to
uncover more information that would point to a solution. Actually, I advise you to
perform this exercise even before you encounter a problem, because an analysis of
the detailed log output will give you a better understanding of how
mlogc works.
File upload interception is a special form of logging, in which the files being uploaded to your server are intercepted, inspected, and stored, and all that before they are seen by an application. The directives related to this feature are in Table 4.6, “File upload directives”, but you’ve already seen them all in the section called “File Uploads”.
Table 4.6. File upload directives
| Directive | Description |
|---|---|
SecUploadDir
| Specifies the location where intercepted files will be stored |
SecUploadFileMode
| Specifies the permissions that will be used for the stored files |
SecUploadKeepFiles
| Specifies whether to store the uploaded files (On,
Off, or RelevantOnly) |
Assuming the default configuration suggested in this guide, you only need to
change the setting of the SecUploadKeepFiles directive to
On to start collecting uploaded files. If, after a few file
upload requests, you examine /opt/modsecurity/var/upload, you’ll
find files with names similar to these:
20090818-164623-SorMz38AAAEAAFG2AOAAAAAA-file-ok0c4T 20090818-164713-SorNAX8AAAEAAFG4AbUAAAAC-file-2ef1eC
You can probably tell that the first two parts of a filename are based on the time
of upload, then follows the unique transaction ID, the -file-
part that is always the same, and a random string of characters at the end.
ModSecurity uses this algorithm to generate file names primarily to avoid filename
collision and support the storage of a large number of files in a folder. In
addition, avoiding the use of a user-supplied file name prevents a potential
attacker from placing a file with a known name on a server.
When you store a file like this, it is just a file and it doesn’t tell you anything about the attacker. Thus, for the files to be useful, you also need to preserve the corresponding audit log entries, which will contain the rest of the information.
For most people, a more reasonable SecUploadKeepFiles setting
is RelevantOnly, which enables the storage of only the files that
have failed inspection in some way. For this setting to make sense, you need to have
at least one external inspection script along with a rule that invokes it.
A file inspection rule is rather simple:
SecRule FILES_TMPNAMES "@inspectFile /opt/modsecurity/bin/file-inspect.pl" \
phase:2,t:none,log,blockThis example rule will invoke the script
/opt/modsecurity/bin/file-inspect.pl for every uploaded
file. The script will be given the location of the temporary file as its first and
only parameter. It can do whatever it wants with the contents of the file, but it is
expected to return a single line of output that consists of a verdict
(1 if everything is in order and 0 for a
fault), followed by an error message. For example:
1 OK
0 Error
Following are the debug log lines produced by the inspection file:
[4] Recipe: Invoking rule 99e6538; [file "/opt/modsecurity/etc/rules.conf"] ↩ [line "3"]. [5] Rule 99e6538: SecRule "FILES_TMPNAMES" "@inspectFile ↩ /opt/modsecurity/bin/file-inspect.pl" "phase:2,auditlog,t:none,log,block" [4] Transformation completed in 2 usec. [4] Executing operator "inspectFile" with param ↩ "/opt/modsecurity/bin/file-inspect.pl" against FILES_TMPNAMES:f. [9] Target value: ↩ "/opt/modsecurity/var/tmp//20090819-181304-SowyoH8AAQEAACW1AIo-file-ZPtFAq" [4] Executing /opt/modsecurity/bin/file-inspect.pl to inspect ↩ /opt/modsecurity/var/tmp//20090819-181304-SowyoH8AAQEAACW1AIoAAAAA-file-ZPtFAq. [9] Exec: /opt/modsecurity/bin/file-inspect.pl [4] Exec: First line from script output: "1 OK" [4] Operator completed in 6969 usec. [4] Rule returned 0.
If an error occurs, for example if you make a mistake in the name of the script, you’ll get an error message that looks similar to this one:
[9] Exec: /opt/modsecurity/bin/file_inspect.pl [1] Exec: Execution failed while reading output: ↩ /opt/modsecurity/bin/file_inspect.pl (End of file found)
If you write your inspection scripts in Lua, ModSecurity will be able to execute them directly using an internal Lua engine. The internal execution will not only be faster, but from the Lua scripts you will be able to access the complete transaction context (which is not available to any external programs).
ClamAV (http://www.clamav.net) is a popular open source anti-virus
program. If you have it installed, the following script will allow you to utilize it
to scan files from ModSecurity:
#!/usr/bin/perl
$CLAMSCAN = "/usr/bin/clamscan";
if (@ARGV != 1) {
print "Usage: modsec-clamscan.pl FILENAME\n";
exit;
}
my ($FILE) = @ARGV;
$cmd = "$CLAMSCAN --stdout --disable-summary $FILE";
$input = `$cmd`;
$input =~ m/^(.+)/;
$error_message = $1;
$output = "0 Unable to parse clamscan output";
if ($error_message =~ m/: Empty file\.$/) {
$output = "1 empty file";
}
elsif ($error_message =~ m/: (.+) ERROR$/) {
$output = "0 clamscan: $1";
}
elsif ($error_message =~ m/: (.+) FOUND$/) {
$output = "0 clamscan: $1";
}
elsif ($error_message =~ m/: OK$/) {
$output = "1 clamscan: OK";
}
print "$output\n";If you need a file to test with, you can download one from
http://www.eicar.org/anti_virus_test_file.htm. The files at this
location contain a test signature that will be picked up by ClamAV.
The error message from the integration script will return either the result of the inspection of the file or an error message if the inspection process failed. Following is an example that shows a successful detection of a “virus”:
[9] Exec: /opt/modsecurity/bin/modsec-clamscan.pl [4] Exec: First line from script output: "0 clamscan: Eicar-Test-Signature" [4] Operator completed in 2137466 usec. [2] Warning. File ↩ "/opt/modsecurity/var/tmp//20090819-181833-Sowz6X8AAQEAACXQAWAAAAAB-file-logg59" ↩ rejected by the approver script "/opt/modsecurity/bin/modsec-clamscan.pl": 0 ↩ clamscan: Eicar-Test-Signature [file "/opt/modsecurity/etc/rules.conf"] [line "3"]
If you look carefully at the example output, you’ll see that the inspection took
in excess of 2 seconds. This is not unusual (even for my slow virtual server),
because we’re creating a new instance of the ClamAV engine for every inspection. The
scanning alone is fast, but the initialization takes considerable time. A more
efficient method would be to use the ClamAV daemon (e.g., the
clamav-daemon package on Debian) for inspection. In this
case, the daemon is running all the time, and the script is only informing it that
it needs to inspect a file.
Assuming you’ve followed the recommendation for the file permissions settings given in the section called “Folder Locations”, this is what you need to do:
An examination of the logs after the change in the configuration will tell you that there’s been a significant improvement—from seconds to milliseconds:
[9] Exec: /opt/modsecurity/bin/modsec-clamscan.pl [4] Exec: First line from script output: "0 clamscan: Eicar-Test-Signature" [4] Operator completed in 13329 usec. [2] Warning. File ↩ "/opt/modsecurity/var/tmp//20090819-182404-Sow1NH8AAQEAACiEAIcAAAAA-file-AMzbgK" ↩ rejected by the approver script "/opt/modsecurity/bin/modsec-clamscan.pl": 0 ↩ clamscan: Eicar-Test-Signature [file "/opt/modsecurity/etc/rules.conf"] [line "3"]
By now you have seen how you have many facilities you can use to configure logging to work exactly as you need it. The facilities can be grouped into four categories:
The various audit logging configuration directives establish the default (or static) audit logging configuration. You should use this type of configuration to establish what you want to happen in most cases. You should then use the remaining configuration mechanisms (listed next) to create exceptions to handle edge cases.
Every rule match, unless suppressed, increments the transaction’s
relevant flag. This handy feature, designed to work
with the RelevantOnly setting of
SecAuditEngine, allows you to trigger transaction
logging when something unusual happens.
Rule matching and the actions auditlog and
noauditlog do not control logging directly. They
should be viewed as mere suggestions—it is up to the engine to decide
whether to log a transaction. They are also ephemeral, affecting only the
rules with which they are associated. They will be forgotten as the
processing moves onto the next rule.
Rules can make logging decisions that affect entire decisions (through the
ctl action), but that functionality should not be
used lightly. Most rules should be concerned only with event generation,
restricting their decisions to the suggestions mentioned in the previous.
The ability to affect transaction logging should be used by system rules
placed in phase 5 and written specifically for the purpose of logging
control.
Using the SecAuditLogParts directive, you will configure
exactly what parts (how much information) you want logged for every transaction, but
one setting will not be adequate in all cases. For example, most configurations will
not be logging response bodies, but that information is often required to determine
whether certain types of attack (XSS, for example) were successful.
The following rule will detect only simple XSS attacks, but when it does, it will cause the transaction’s response body to be recorded:
SecRule ARGS <script> phase:2,log,block,ctl:auditLogParts=+E
The feature discussed in the previous section is very useful, but you may not always like the fact that some rules are changing what you’re logging. I know I would not. Luckily, it’s a problem that can be resolved with an addition of a phase 5 rule that resets the logged audit log parts:
SecAction phase:5,nolog,pass,ctl:auditLogParts=ABCDFGH
You can then decide on your own whether the logging of part E
is justified. If you are using full audit logging in particular, you will need to
manually increase the amount you log per transaction. The
HIGHEST_SEVERITY variable, which contains the highest
severity of the rules that matched during a transaction, is particularly
useful:
SecRule HIGHEST_SEVERITY "@le 2" phase:5,nolog,pass,ctl:auditLogParts=+E
Most web application programmers are taught to always use POST methods for the
transactions that contain sensitive data. After all it is well known that request
bodies are never logged, meaning that the sensitive data will never be logged,
either. ModSecurity changes this situation, because it allows for full transaction
logging. To deal with the sensitive data that may find its way into the logs,
ModSecurity uses the sanitation actions sanitiseArg,
sanitiseRequestHeader and
sanitiseResponseHeader, and
sanitiseMatched. You basically just need to tell ModSecurity
which elements of a transaction you want removed and it will remove them for you,
replacing their values in the log with asterisks. The first three actions all
require parameters that you will typically know at configuration time, which means
that you will invoke them unconditionally with SecAction.
Sanitation works when invoked from any phase, but you should always use phase 5,
which is designed for this type of activity.
Use sanitiseArg to prevent the logging of the parameters whose
names you know. For example, let’s assume that you have an application that uses the
parameters password, oldPassword, and
newPassword to transmit, well, passwords. This is what you’ll
do:
SecAction "phase:5,nolog,pass,\
sanitiseArg:password,\
sanitiseArg:oldPassword,\
sanitiseArg:newPassword"Similarly, use sanitiseRequestHeader and
sanitiseResponseHeader to remove the contents of the headers
whose names you know. For example, if you have an application that uses HTTP Basic
Authentication, you will need the following rule to prevent the passwords from being
logged:
SecAction "phase:5,nolog,pass,\
sanitiseRequestHeader:Authorization"The last action, sanitiseMatched, is used when you need to
sanitize a parameter whose name you don’t know in advance. My first example will
sanitize the contents of every parameter that has the word password in the
name:
SecRule ARGS_NAMES password "phase:5,nolog,pass,\
sanitiseMatched"In the following example, we look for anything that resembles a credit card number and then sanitize it:
SecRule ARGS "@verifyCC \d{13,16}" "phase:5,nolog,pass,\
sanitiseMatched"Finally, the sanitiseMatchedBytes action,
available as of ModSecurity version 2.6.0, can remove only the parts of input that
contain sensitive information and not entire parameters. This action works only in
conjunction with operators that are based on regular expressions (e.g.,
@rx, @verifyCC, etc.), and further
requires the capture action to be specified.
SecRule ARGS "@verifyCC \d{13,16}" "phase:5,nolog,pass,\
capture,sanitiseMatchedBytes"When further parameters are specified, this new operator can even leave parts of the sensitive data in the log. In the following example, we leave the first four digits and the last four digits of a credit card number:
SecRule ARGS "@verifyCC \d{13,16}" "phase:5,nolog,pass,\
capture,sanitiseMatchedBytes:4/4"Although full transaction logging (the logging of every single byte of every single transaction) sounds good in theory, in practice it is very difficult to use, because it slows down your sever and requires huge amounts of storage space. There are ways to get some of the same benefits for a fraction of cost by using partial full logging on demand.
The trick is to tie in logging to the tracking of IP addresses, users, or sessions. By default you will log only what is relevant, but when you spot something suspicious coming from (for example) an IP address, you may change your logging configuration to turn on full logging for the offending IP address only. Here’s how.
First you need to set up IP address tracking. You do this only once for all your rules, so it should usually be part of your main configuration:
SecAction phase:1,nolog,pass,initcol:ip=%{REMOTE_ADDR}Now you need to add a phase rule that will trigger logging when something else
happens. In the following case, we want to start logging everything coming from an
IP address after a single rule match. To achieve that, we set the flag
ip.logflag for up to one hour (3600 seconds):
SecRule HIGHEST_SEVERITY "@gt 0" \
phase:5,nolog,pass,setvar:ip.logflag=1,expirevar:ip.logflag=3600Finally, we add a rule that detects the flag and forces logging:
SecRule IP:logflag "@gt 0" \
phase:5,nolog,pass,ctl:auditLogEngine=OnThis chapter, along with the two before it, covered the configuration of ModSecurity. You learned how to install ModSecurity and how to configure it, with special attention given to the logging facilities. Logging deserved its own chapter, because configuring a tool to perform certain actions is often only half of the entire story, with the other half consisting of tracking exactly what happened and why. Further, remote logging is a gateway to other systems, which may assist you in managing ModSecurity.
The next three chapters discuss a new topic: rule writing. You’ll first read an overview of the entire rule language, followed by a tutorial in rule writing and then by a higher-level discussion on how to place ModSecurity configuration within Apache’s own directives. Finally, the interesting bits are here!