Apache Logging

Because Apache is an HTTP server at heart, it contains fantastically flexible logging features. It's beyond the scope of this book to discuss all ways logging can be configured, but we should point out that even the most generic httpd.conf file will cause Apache to produce two logs: error_log and access_log. These logs may appear in different places, but are typically created in the logging area of your Apache installation. (On Unix, they often live in /usr/local/apache2/logs/.)

The error_log describes any internal errors that Apache runs into as it works. The access_log file records every incoming HTTP request received by Apache. This makes it easy to see, for example, which IP addresses Subversion clients are coming from, how often particular clients use the server, which users are authenticating properly, and which requests succeed or fail.

Unfortunately, because HTTP is a stateless protocol, even the simplest Subversion client operation generates multiple network requests. It's very difficult to look at the access_log and deduce what the client was doing—most operations look like a series of cryptic PROPPATCH, GET, PUT, and REPORT requests. To make things worse, many client operations send nearly-identical series of requests, so it's even harder to tell them apart.

mod_dav_svn, however, can come to your aid. By activating an “operational logging” feature, you can ask mod_dav_svn to create a separate log file describing what sort of high-level operations your clients are performing.

To do this, you need to make use of Apache's CustomLog directive (which is explained in more detail in Apache's own documentation). Be sure to invoke this directive outside of your Subversion Location block:

<Location /svn>
  DAV svn
  …
</Location>

CustomLog logs/svn_logfile "%t %u %{SVN-ACTION}e" env=SVN-ACTION

In this example, we're asking Apache to create a special logfile svn_logfile in the standard Apache logs directory. The %t and %u variables are replaced by the time and username of the request, respectively. The really important part are the two instances of SVN-ACTION. When Apache sees that variable, it substitutes the value of the SVN-ACTION environment variable, which is automatically set by mod_dav_svn whenever it detects a high-level client action.

So instead of having to interpret a traditional access_log like this:

[26/Jan/2007:22:25:29 -0600] "PROPFIND /svn/calc/!svn/vcc/default HTTP/1.1" 207 398
[26/Jan/2007:22:25:29 -0600] "PROPFIND /svn/calc/!svn/bln/59 HTTP/1.1" 207 449
[26/Jan/2007:22:25:29 -0600] "PROPFIND /svn/calc HTTP/1.1" 207 647
[26/Jan/2007:22:25:29 -0600] "REPORT /svn/calc/!svn/vcc/default HTTP/1.1" 200 607
[26/Jan/2007:22:25:31 -0600] "OPTIONS /svn/calc HTTP/1.1" 200 188
[26/Jan/2007:22:25:31 -0600] "MKACTIVITY /svn/calc/!svn/act/e6035ef7-5df0-4ac0-b811-4be7c823f998 HTTP/1.1" 201 227
…

… you can instead peruse a much more intelligible svn_logfile like this:

[26/Jan/2007:22:24:20 -0600] - list-dir '/'
[26/Jan/2007:22:24:27 -0600] - update '/'
[26/Jan/2007:22:25:29 -0600] - remote-status '/'
[26/Jan/2007:22:25:31 -0600] sally commit r60

For an exhaustive list of all actions logged, see the section called “High Level Logging”.