> ModSecurity Handbook: Getting Started: Chapter 4. Logging


Contents
Previous
Next

4 Logging

This chapter covers the logging capabilities of ModSecurity in detail. Logging is a big part of what ModSecurity does, so it’s not surprising that there are extensive logging facilities available for your use.

Debug Log

The debug log is going to be your primary troubleshooting tool, especially initially, while you’re learning how ModSecurity works. You’re 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.

Table 4.1. Debug log directives

DirectiveDescription
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. Messages with levels 1–3 are copied to Apache’s error log. The higher-level messages are there mostly for troubleshooting and debugging.

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 having the messages only in the error log). 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 transaction consumes a lot of resources.

This is what a single debug log line looks like:

[24/Jul/2016:17:38:25 +0200] [192.168.3.111/sid#15e21f8][rid#7f683c002970]↩
[/index.html][4] Initialising transaction (txid V5Tg8X8AAQEAABXZdiwAAAAA).

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.

Table 4.2. Debug log levels

Debug log levelDescription
0No logging
1Errors (e.g., fatal processing errors, blocked transactions)
2Warnings (e.g., nonblocking rule matches)
3Notices (e.g., nonfatal processing errors)
4Handling of transactions and performance
5Detailed syntax of the rules
6–8Not used
9Detailed information about transactions (e.g., variable expansion and setting of variables)

There’s another reason to avoid extensive debug logging in production, and that’s simply that it’s very difficult. There’s usually so much data that it sometimes takes ages to find the messages that pertain to the transaction you want to investigate. In spite of the difficulties, you may occasionally need to debug in production because you can’t reproduce a problem elsewhere.

Note

The audit log can record all the rules that matched during an HTTP transaction. This helpful feature 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 want to debug. You can do this by overriding the default configuration, using the <Location> context directive, as shown ahead. While you’re doing that, it may be a good idea to specify a different debug log file altogether. That way, you’ll keep the main debug log file free of your tests.

<Location /myapp/>
    SecDebugLogLevel 9
    SecDebugLog /usr/local/modsecurity/var/log/troubleshooting.log
</Location>

This approach, although handy, still doesn’t 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 a specific client sends. 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 by 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 "@ipMatch 192.168.1.1" \
    id:1000,phase:1,pass,nolog,ctl:debugLogLevel=9

Using your IP address won’t work in cases in which you’re hidden by a network address translation 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’s done depends on the browser you’re using.)

SecRule REQUEST_HEADERS:User-Agent "@contains YOUR_UNIQUE_ID" \
    id:1000,phase:1,pass,nolog,ctl:debugLogLevel=9

This 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 to dynamically enable 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 a request-by-request basis, using one of the tools that support request interception and modification. You can do so via a browser extension or can use an interception proxy. 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. While you’re at it, it’s 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 of lines.

Audit Log

It’s a little-known fact that the earliest versions of ModSecurity essentially had one feature: the ability to record complete HTTP transaction data. Being able to see exactly what’s exchanged between browsers and servers is very important for developers, yet few web servers make it possible. The audit log, which does just that, was one of the first features implemented.

ModSecurity is currently able to log most, but not all, transactions. Transactions involving errors (e.g., 400 and 404 transactions) and some third-party Apache modules like mod_auth_cas use a different execution path, which ModSecurity doesn’t support. This means that they shortcut the ModSecurity rule phases 1 to 4, effectively preventing the module from extracting the necessary data out of the request. Audit log directives are shown in Table 4.3.

Table 4.3. Audit log directives

DirectiveDescription
SecAuditEngine Controls the audit log engine; possible values are On, Off, or RelevantOnly
SecAuditLog Path to an audit log file
SecAuditLog2 Path to another audit log file (copy)
SecAuditLogDirMode Permissions (mode) of the folders created for the concurrent log type
SecAuditLogFileMode Permissions (mode) of the files created for the concurrent log type
SecAuditLogFormat Format of the audit log (native or JSON)
SecAuditLogParts Specifies which part of a transaction will be logged
SecAuditLogRelevantStatus Specifies which response statuses will be considered relevant
SecAuditLogStorageDir Path where 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, brief User-Agent, without a body, and no logging of the response body) consumes around 1.5 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. There is a native format for the individual entries or an alternative JSON format. Looking at a single audit log entry in the default native format, 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 parts A and Z are mandatory; the use of the other parts is controlled with the SecAuditLogParts directive. Table 4.4 contains the list of all audit log parts, along with a description of their purpose.

Table 4.4. Audit log parts

Part letterDescription
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 Reduced multipart request body, which excludes files (alternative to part C)
J Information on uploaded files (multipart requests)
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:

--be58b513-A--
[27/Jul/2016:05:46:16 +0200] V5guiH8AAQEAADTeJ2wAAAAK 192.168.3.1 50084 192.168.3.111 80

Part B contains the request headers and nothing else:

POST /index.html?a=test HTTP/1.1
Host: example.com
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
Referer: http://example.com/index.html
Connection: keep-alive
Content-Type: application/x-www-form-urlencoded
Content-Length: 6

Part C contains the raw request body, typically that of a POST request:

--be58b513-C--
b=test

Part F contains the response headers:

--be58b513-F--
HTTP/1.1 200 OK
Last-Modified: Sun, 24 Jul 2016 15:24:49 GMT
ETag: "2d-5386344b7871a"
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:

--be58b513-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:

--be58b513-H--
Stopwatch: 1470025005945403 1715 (- - -)
Stopwatch2: 1470025005945403 1715; combined=26, p1=0, p2=0, p3=0, p4=0, p5=26, ↩
sr=0, sw=0, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.9.1 (http://www.modsecurity.org/).
Server: Apache
Engine-Mode: "ENABLED"

Part K contains a list of rules that matched in a transaction. It isn’t unusual for this part to be empty, but if you have a complex ruleset, it may show quite a few rules. Audit logs that record transactions for 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:

--be58b513-K--
SecAction "phase:2,auditlog,log,pass,msg:'Matching test'"

Every audit log file ends with the terminating boundary, which is part Z:

--be58b513-Z--

The JSON audit log format was introduced with ModSecurity 2.9.1. It’s enabled via the SecAuditLogFormat directive. It’s conceptually similar to the native format, but organizes information in a different way. The native audit log parts can be roughly mapped to the JSON format blocks in the following way:

More information about this additional audit log format is available in the Data Formats chapter.

Initially, ModSecurity supported only the serial audit logging type. Concurrent logging was introduced to address two issues:

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 be created not directly in the folder specified by SecAuditLogStorageDir but in an elaborate structure of subfolders, the names of which will be constructed from the current date and time:

20160727
20160727/20160727-0546
20160727/20160727-0546/20160727-054616-V5guiH8AAQEAADTeJ2wAAAAK
20160727/20160727-0546/20160727-054616-V5guBH8AAQEAADTeJ2cAAAAA

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 type 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 - - [27/Jul/2016:05:46:16 +0200] "GET / HTTP/1.1" 200 218 "-" "-" V5guiH8AAQEAADTeJ2wAAAAK "-" /20160727/20160727-0546/20160727-054616-V5guiH8AAQEAADTeJ2wAAAAK 0 1592 md5:48e90bf2a5ab9e7368d8b579f14bf82b

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 twofold:

When real-time audit log centralization is used, this information isn’t written to a file. Instead, it’s written to a pipe, which means that it’s sent directly to another process, which deals with the information immediately. You’ll see how that works in the next section.

Remote Logging

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:

Secure

The communication path between your ModSecurity sensors and the remote logging server is secured with SSL and authenticated using HTTP basic authentication.

Efficient

Remote logging is implemented with multiple threads of execution, which allow for many alerts to be handled in parallel. Existing HTTP connections are reused.

Reliable

An audit log entry will be deleted from the sensor only once its safe receipt is acknowledged by the logging server.

Buffered

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.

Note

Remote logging uses a simple but effective protocol based on HTTP. You’ll find it documented in Chapter 20, Data Formats.

If you’ve followed my installation instructions, you’ll have mlogc compiled and sitting in your bin/ folder. To proceed, you’ll need to configure it, then add it to the ModSecurity configuration.

Remote logging in ModSecurity is implemented through an elaborate scheme designed to minimize the possibility of data loss. Here’s how it’s done:

  1. ModSecurity processes a transaction and creates an audit log entry file on disk, as explained in the section called “Concurrent Audit Log” earlier in this chapter.

  2. ModSecurity then notifies the mlogc tool, which runs in a separate process. The notification contains enough information to locate the audit log entry file on disk.

  3. The mlogc tool adds the audit log entry information to the in-memory queue and to its transaction log (the mlogc-transaction.log file by default).

  4. One of many worker threads that run within mlogc takes the audit log entry and submits it to a remote logging server. The entry is then removed from the in-memory queue and the transaction log is notified.

  5. A periodic checkpoint operation, initiated by mlogc, writes the in-memory queue to the disk (to the mlogc-queue.log file by default) and erases the transaction log.

If mlogc crashes, Apache will restart it automatically. When an unclean shutdown is detected, mlogc will reconstruct the entry queue using the last known good point (the on-disk queue) and the record of all events since the moment the on-disk queue was created, which are stored in the transaction log.

The mlogc configuration file is similar to that of Apache, only simpler. We usually place it in /usr/local/modsecurity/etc/mlogc.conf. First, we need to tell mlogc where its “home” is, which is where it will create its log files. The mlogc log files are very important, because—as it’s 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  /usr/local/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 mlogc 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 /usr/local/modsecurity/var/audit

Next, we need to tell mlogc where to submit 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 usually 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

# If network communication fails, suspend log
# submission to give the server time to recover.
ServerErrorTimeout  60

Note

The mlogc tool will take audit log entries created by ModSecurity, submit them to a remote logging server, and delete them from disk, but it will leave the empty folders (that were used to store the entries) behind. You’ll have to remove them yourself, either manually or with a script.

You’ll 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 "|/usr/local/modsecurity/bin/mlogc ↩
/usr/local/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.

Please note that you still need to configure SecAuditLogStorageDir because ModSecurity will refuse to work properly without it. Your complete configuration should look like this now:

SecAuditEngine RelevantOnly
SecAuditLogRelevantStatus ^5
SecAuditLogParts ABDEFHIJKZ
SecAuditLogType Concurrent
SecAuditLog "|/usr/local/modsecurity/bin/mlogc ↩
/usr/local/modsecurity/etc/mlogc.conf"
SecAuditLogStorageDir /usr/local/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  /usr/local/modsecurity/bin/mlogc ↩
/usr/local/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:

-rw-r-----  1 root     root  83K Jul 29 15:12 audit.log
-rw-r-----  1 root     root  68M Jul 29 15:12 debug.log
-rw-r--r--  1 root     root  769 Jul 30 05:31 mlogc-error.log
-rw-r--r--  1 root     root    0 Jul 30 05: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] [5877/0] Configuring ModSecurity Audit Log Collector 2.9.1.
[3] [5877/0] Delaying execution for 5000ms.
[3] [5897/0] Configuring ModSecurity Audit Log Collector 2.9.1.
[3] [5897/0] Delaying execution for 5000ms.
[3] [5877/0] Queue file not found. New one will be created.
[3] [5877/0] Caught SIGTERM, shutting down.
[3] [5877/0] ModSecurity Audit Log Collector 2.9.1 terminating normally.
[3] [5897/0] Queue file not found. New one will be created.

It’s 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 5877 and PID 5897). 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, 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—that is, it will report the problem and shut down. (Don’t be surprised if Apache continues to attempt to start it. That’s what Apache does with piped logging programs.)

If you make a mistake in defining the error log, you may get an error message in response to the attempt to start Apache. The following is the error message you’d get if you left ErrorLog undefined:

dev:/usr/local/modsecurity/etc# apache2ctl start
[1] [15997/0] Failed to open the error log (null): Bad address
[3] [15997/0] ModSecurity Audit Log Collector 2.9.1 terminating with error 1

If mlogc manages to open its error log, it will do what’s expected and write all error messages there. For example:

[1] [16402/0] QueuePath not defined in the configuration file.
[3] [16402/0] ModSecurity Audit Log Collector 2.9.1 terminating with error 1

At this point, it’s 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 the default logging configuration (level 3), a single audit log entry handled by mlogc will produce one line in the log file:

[3] [1748/7f65840009c0] Entry completed (0.109 seconds, 1415 bytes): ↩
V5w0Rn8AAQEAAAbptJUAAABC

That’s basically all you need to know—that an entry has been safely transmitted to the intended destination. You’ll get more information when something goes wrong, of course. For example, you’ll see the following message whenever your logging server goes down:

[2] [23743/7ff2840009c0] Flagging server as errored after failure to submit entry V5wthX8AAQEAAE1D3OYAAAAE (cURL code 7): Failed to connect ↩
to loghost port 8888: Connection refused

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 see the following information in the log:

[3] [1748/7f65840009c0] Clearing the server error flag after successful entry ↩
submission: V5w1WX8AAQEAAAerQowAAADA
[3] [1748/7f65840009c0] Entry completed (0.887 seconds, 1415 bytes): ↩
V5w1WX8AAQEAAAerQowAAADA

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. See Table 4.5 for the description of the most common problems.

Table 4.5. Common remote logging problems

Error messageDescription
Failed to connectThe server could not be reached. This 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 errorMost often, this message means that you configured mlogc to submit over plaintext, but the remote server uses SSL. Make sure the ConsoleURI parameter starts with https://.
UnauthorizedThe credentials are incorrect. Check the SensorUsername and SensorPassword parameters.
For input string: “0, 0”A remote server can indicate an internal error, but such errors are treated as transient.

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

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, but you’ve already seen them all in the section called “File Uploads” in Chapter 3, Configuration.

Table 4.6. File upload directives

DirectiveDescription
SecUploadDir Specifies the location where intercepted files will be stored
SecUploadFileLimit Specifies the maximum number of file uploads processed
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 /usr/local/modsecurity/var/upload, you’ll find files with names similar to these:

20160728-102354-V5nBGn8AAQEAACo1bNgAAAAA-file-b9irlZ
20160728-102354-V5nBGn8AAQEAACo1bNkAAAAC-file-TeZQZF

You can probably tell that the first two parts of a filename are based on the time of upload, then the unique transaction ID follows, then the -file- part that is always the same, and finally a random string of characters at the end. ModSecurity uses this algorithm to generate filenames 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 filename prevents a potential attacker from placing a file with a known name on a server.

When you store a file like this, it’s just a file and 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.

Note

Storage of intercepted files can potentially consume a lot of disk space. If you’re doing it, you should at least ensure that the filesystem that you’re using for storage is not the root filesystem; you don’t want an overflow to kill your entire server.

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.

There are four separate variables involved with file uploads, and you need to pick the right one for the inspection:

The best way to inspect a file is to pass the temporary filename to an inspection script, so we settle on the FILES_TMPNAMES variable. Once this is clear, a file inspection rule is rather simple:

SecRule FILES_TMPNAMES "@inspectFile /usr/local/modsecurity/bin/file-inspect.pl" \
    id:2000,phase:2,block,t:none,log

This example rule will invoke the /usr/local/modsecurity/bin/file-inspect.pl script 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’s 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

Or:

0 Error

The alert message in the audit log will only display the verdict, but the debug log will display the full error message. The following debug log lines are produced by the inspection file:

[4] Recipe: Invoking rule 2735e58; [file "/usr/local/apache/conf/httpd.conf_pod_2016-07-28_10:10"] [line "238"] [id "2000"].
[5] Rule 2735e58: SecRule "FILES_TMPNAMES" "@inspectFile /usr/local/apache/bin/inspect-file.pl" "phase:2,id:2000,block,t:none,log"
[4] Transformation completed in 1 usec.
[4] Executing operator "inspectFile" with param "/usr/local/modsecurity/bin/file-inspect.pl" against FILES_TMPNAMES:f.
[9] Target value: "/tmp//20160728-103559-V5nD738AAQEAAD5bgsAAAAAA-file-yfp59Q"
[4] Executing /usr/local/apache/bin/file-inspect.pl to inspect /usr/local/modsecurity/var/tmp/↩
20160728-103559-V5nD738AAQEAAD5bgsAAAAAA-file-yfp59Q.
[9] Exec: /usr/local/apache/bin/file-inspect.pl
[4] Exec: First line from script output: "1 OK"
[4] Operator completed in 2722317 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: /usr/local/modsecurity/bin/file_inspect.pl
[1] Exec: Execution failed while reading output: /usr/local/modsecurity/bin/file_inspect.pl (End of file found)

Tip

If you write your inspection scripts in Lua, ModSecurity will be able to execute them directly using an internal Lua engine. Not only will the internal execution be faster, but from the Lua scripts you’ll be able to access the complete transaction context (which isn’t available to any external programs).

ClamAV 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 $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";

Note

If you need a file to test with, you can download one from EICAR’s web site.19 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. The following example shows a successful detection of a “virus”:

[9] Exec: /usr/local/modsecurity/bin/modsec-clamscan.pl
[4] Exec: First line from script output: "0 clamscan: Eicar-Test-Signature"
[4] Operator completed in 2628132 usec.
[2] Warning. File 
"/usr/local/modsecurity/var/tmp/20160728-110518-V5nKzn8AAQEAAD5bgsEAAAAC-file-szWj6L" rejected by the approver script "/usr/local/modsecurity/bin/modsec-clamscan.pl": 0 clamscan: Eicar-Test-Signature [file "/usr/local/modsecurity/etc/rules.conf"] [line "238"] [id "2000"]

If you look carefully at the example output, you’ll see that the inspection took more than two seconds. This isn’t 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” in Chapter 3, Configuration, this is what you need to do:

  1. Change the name of the ClamAV script from clamscan to clamdscan (note the added d in the filename).

  2. Add the ClamAV user (typically clamav) to the apache group (don’t forget to restart the ClamAV daemon to pick up the new group).

  3. Relax the default file permissions used for uploaded files to allow group read by changing SecUploadFileMode from 0600 to 0640.

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: /usr/local/modsecurity/bin/modsec-clamscan.pl
[4] Exec: First line from script output: "0 clamdscan: Eicar-Test-Signature"
[4] Operator completed in 20581 usec.
[2] Warning. File "/usr/local/modsecurity/var/tmp/20160728-111500-V5nNFH8AAQEAAGO1b38AAAAA-file-vSR2dT" rejected by the approver script "/usr/local/modsecurity/bin/modsec-clamscan.pl": 0 clamscan: Eicar-Test-Signature [file "/usr/local/modsecurity/etc/rules.conf"] [line "239"] [id "2000"]

Advanced Logging Configuration

By now, you’ve 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:

Static logging configuration

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.

Setting of the relevant flag on rule matches

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.

Per-rule logging suggestions

Rule matching and the auditlog and noauditlog actions don’t control logging directly. They should be viewed as mere suggestions; it’s 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 on to the next rule.

Dynamic logging configuration

Rules can make logging decisions that affect entire requests (through the ctl action), but that functionality shouldn’t be used lightly. Most rules should be concerned only with event generation. 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.

The SecAuditLogParts directive allows you to configure exactly what parts (how much information) you want logged for every transaction, but one setting won’t be adequate in all cases. For example, most configurations won’t be logging response bodies, but that information is often required to determine whether certain types of attacks (e.g., XSS) 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 "@rx <script>" \
    id:2000,phase:2,block,log,ctl:auditLogParts=+E

The feature discussed in the previous section is very useful, but you may not always like the fact that some rules change what you’re logging. I know I wouldn’t! Luckily, it’s a problem that can be resolved with the addition of a phase 5 rule that resets the logged audit log parts:

SecAction id:9000,phase:5,pass,nolog,ctl:auditLogParts=ABCDFGH

You can then decide on your own whether the logging of part E is justified. If you’re using full audit logging in particular, you’ll 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" \
    id:9000,phase:5,pass,nolog,ctl:auditLogParts=+E

Most web application programmers are taught always to use POST methods for transactions that contain sensitive data. After all, it’s well known that request bodies are never logged, meaning that sensitive data will never be logged, either. ModSecurity changes this situation, because it allows for full transaction logging. To deal with sensitive data that may find its way into the logs, ModSecurity uses the sanitiseArg, sanitiseRequestHeader, sanitiseResponseHeader, sanitiseMatched, and sanitiseMatchedBytes sanitization actions. 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. Sanitization 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 for which you know the names. For example, let’s assume that you have an application that uses the password, oldPassword, and newPassword parameters to transmit, well, passwords. This is what you’ll do:

SecAction "id:9000,phase:5,pass,nolog,\
    sanitiseArg:password,\
    sanitiseArg:oldPassword,\
    sanitiseArg:newPassword"

Similarly, use sanitiseRequestHeader and sanitiseResponseHeader to remove the contents of the headers for which you know the names. For example, if you have an application that uses HTTP basic authentication, you’ll need the following rule to prevent passwords from being logged:

SecAction "id:9000,phase:5,pass,nolog,\
    sanitiseRequestHeader:Authorization"

The last action, sanitiseMatched, is used when you need to sanitize a parameter for which you don’t know the name in advance. My first example will sanitize the contents of every parameter that has the word password in the name:

SecRule ARGS_NAMES "@rx password" \
    "id:9000,phase:5,pass,nolog,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}" \
    "id:9000,phase:5,pass,nolog,sanitiseMatched"

Finally, the sanitiseMatchedBytes action can remove the parts of input that contain sensitive information only, rather than 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}" \
    "id:9000,phase:5,pass,capture,nolog,sanitiseMatchedBytes"

When further parameters are specified, this new operator can even leave parts of the sensitive data in the log. The following example leaves the first four and the last four digits of a credit card number in the log:

SecRule ARGS "@verifyCC \d{13,16}" \
    "id:9000,phase:5,pass,capture,nolog,sanitiseMatchedBytes:4/4"

Warning

The sanitization actions work only for the data recorded in the audit log. However, sensitive data could end up in the error log if it’s involved in a rule match, depending on the logging configuration of the rule. Likewise, sanitization doesn’t work with XML and JSON request bodies.

Although full HTTP transaction logging sounds good in theory, in practice it’s very difficult to use, because it slows down your server and requires large amounts of storage space. There are ways to get some of the same benefits for a fraction of the cost by using partial logging on demand.

The trick is to tie logging into the tracking of IP addresses, users, or sessions. By default, you’ll log only what’s relevant, but when you spot something suspicious coming from (for example) an IP address, you can change your logging configuration to turn on full logging for the offending IP address only.

To use this functionality, 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 id:1000,phase:1,pass,nolog,initcol:ip=%{REMOTE_ADDR}

Now, you need to add a rule that will trigger logging when one of the rules in the ruleset matches. We assume that all the rules in the ruleset assign a severity to their alerts. The default value for HIGHEST_SEVERITY is 255. Any value below 255 thus indicates that an alert has occurred; in practice, you might choose one of the real severity values, matching only on serious events. The following rule will start logging everything coming from an IP address after such a single rule match; to achieve that, we set the flag ip.logflag for up to one hour (3,600 seconds):

SecRule HIGHEST_SEVERITY "@lt 4" \
    id:9000,phase:5,pass,nolog,setvar:ip.logflag=1,expirevar:ip.logflag=3600

Finally, we add a rule that detects the flag and forces logging for all the requests from the flagged IP address:

SecRule IP:logflag "@gt 0" \
    id:9001,phase:5,pass,nolog,ctl:auditEngine=On

Summary

This 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 a higher-level discussion of how to place ModSecurity configuration within Apache’s own directives. Finally, the interesting bits are here!

[19] EICAR antimalware test file (Retrieved 15 January 2017)