We are defining a greatly extended log format in order to better monitor traffic.<\/p>\n
In the usual configuration of the Apache web server a log format is used that logs only the most necessary information about access from different clients. In practice, additional information is often required, which can easily be recorded in the server\u2019s access log.<\/p>\n
The common<\/em> log format is a very simple format that is hardly ever used any more. It has the advantage of being space-saving and hardly ever writing unnecessary information.<\/p>\n We use the LogFormat<\/em> directive to define a format and give it a name, common<\/em> in this case.<\/p>\n We invoke this name in the definition of the log file using the CustomLog<\/em> directive. We can use these two directives multiple times in the configuration. Thus, multiple log formats with several name abbreviations can be defined next to one another and log files written in different formats. It\u2019s possible for different services to write to separate log files on the same server.<\/p>\n The individual elements of the common<\/em> log format are as follows:<\/p>\n %h<\/em> designates the remote host<\/em>, normally the IP address of the client making the request. But if the client is behind a proxy server, then we\u2019ll see the IP address of the proxy server here. So, if multiple clients share the proxy server then they will have the same remote host<\/em> entry. It\u2019s also possible to retranslate the IP addresses using DNS reverse lookup on our server. If we configure this (which is not recommended), then the host name determined for the client would be entered here.<\/p>\n %l<\/em> represents the remote log name<\/em>. It is usually empty and output as a hyphen (\u201c-\u201c). In fact, this is an attempt to identify the client via ident<\/em> access to the client. This has little client support and results in the biggest performance bottlenecks which is why %l<\/em> is an artifact from the early 1990s.<\/p>\n %u<\/em> is more commonly used and designates the user name of an authenticated user. The name is set by an authentication module and remains empty (thus the \u201d-\u201d), for as long as access without authentication on the server takes.<\/p>\n %t<\/em> means the time of access. For big, slow requests the time means the moment the server receives the request line. Since Apache writes a request in the log file only after completing the response, it may occur that a slower request with an earlier time may appear several entries below a short request started later. Up to now this has resulted in confusion when reading the log file.<\/p>\n By default, the time is output between square brackets. It is normally the local time including the deviation from standard time. For example:<\/p>\n This means November 25, 2014, 8:51 am, 1 hour before standard time. The format of the time can also be changed if necessary. This is done using the %{format}t<\/em> pattern, where format<\/em> follows the specification of strftime(3)<\/em>. We have already made use of this option in Tutorial 2. But let\u2019s use an example to take a closer look:<\/p>\n In this example we put the date in the order Year-Month-Day<\/em>, to make it sortable. And after the deviation from standard time we add the time in seconds since the start of the Unix age in January 1970. This format is more easily read and interpreted via a script.<\/p>\n This example gives us entries using the following pattern:<\/p>\n So much for %t<\/em>. This brings us to %r<\/em> and the request line. This is the first line of the HTTP request as it was sent from the client to the server. Strictly speaking, the request line does not belong in the group of request headers, but it is normally subsumed along with them. In any case, in the request line the client transmits the identification of the resource it is demanding.<\/p>\n Specifically, the line follows this pattern:<\/p>\n In practice, it\u2019s a simple example such as this:<\/p>\n The GET<\/em> method is being used. This is followed by a space, then the absolute path of the resource on the server. The index file in this case. Optionally, the client can, as we are aware, add a query string<\/em> to the path. This query string<\/em> normally begins with a question mark and comes with a number of parameter value pairs. The query string<\/em> is also output in the log file. Finally, the protocol that is most likely to be HTTP version 1.1. Version 1.0 still continues to be used by some agents (automated scripts). The new HTTP\/2 protocol does not appear in the request line of the initial request. In HTTP\/2 an update from HTTP\/1.1 to HTTP\/2 takes place during the request. The start follows the pattern above.<\/p>\n The following format element follows a somewhat different pattern: %>s<\/em>. This means the status of the response, such as 200<\/em> for a successfully completed request. The angled bracket indicates that we are interesting in the final status. It may occur that a request is passed off within the server. In this case what we are interested in is not the status that passing it off triggered, but the status of the response for the final internal request.<\/p>\n One typical example would be a request that causes an error on the server (Status 500). But if the associated error page is unavailable, this results in status 404 for the internal transfer. Using the angled bracket means that in this case we want 404 to be written to the log file. If we reverse the direction of the angled bracket, then Status 500 would be logged. Just to be certain, it may be advisable to log both values using the following entry (which is not usual in practice):<\/p>\n %b<\/em> is the last element of the common<\/em> log format. It shows the number of bytes announced in the content-length response headers. In a request for http:\/\/www.example.com\/index.html<\/em> this value is the size of the index.html<\/em> file. The response headers<\/em> also transmitted are not counted. And there is an additional problem with this number: It is a calculation by the webserver and not an account of the bytes that have actually been sent in the response.<\/p>\n The most widespread log format, combined<\/em>, is based on the common<\/em> log format, extending it by two items.<\/p>\n \u201c%{Referer}i\u201d<\/em> is used for the referrer. It is output in quotes. The referrer means any resource from which the request that just occurred was originally initiated. This complicated paraphrasing can best be illustrated by an example. Suppose you click a link at a search engine to get to www.example.com<\/em>. But when you send your request, you are automatically redirected to shop.example.com<\/em>. The log entry for shop.example.com<\/em> will include the search engine as the referrer and not the link to www.example.com<\/em>. If however a CSS file dependent on shop.example.com<\/em> is loaded, the referer would normally be attributed to shop.example.com<\/em>. However, despite all of this, the referrer is part of the client\u2019s request. The client is required to follow the protocol and conventions, but can in fact send any kind of information, which is why you cannot rely on headers like these when security is an issue.<\/p>\n Finally, \u201c%{User-Agent}i\u201d<\/em> means the client user agent, which is also placed in quotes. This is also a value controlled by the client and which we should not rely on too much. The user agent is the client browser software, normally including the version, the rendering engine, information about compatibility with other browsers and various installed plugins. This results in very long user agent entries which can in some cases include so much information that an individual client can be uniquely identified, because they feature a particular combination of different add-ons of specific versions.<\/p>\n We have become familiar with the combined<\/em> format, the most widespread Apache log format. However, to simplify day-to-day work, the information shown is just not enough. Additional useful information has to be included in the log file.<\/p>\n It is advisable to use the same log format on all servers. Now, instead of just propagating one or two additional values, these instructions describe a comprehensive log format that has proven useful in a variety of scenarios.<\/p>\n However, in order to be able to configure the log format below, we first have to enable the Logio<\/em> module. And on top if the the Unique-ID module, which useful from the start.<\/p>\n If the server has been compiled as described in Tutorial 1, then these modules are already present and only have to be added to the list of modules being loaded in the server\u2019s configuration file.<\/p>\n We need this module to be able to write two values. IO In<\/em> and IO Out<\/em>. This means the total number of bytes of the HTTP request including header lines and the total number of bytes in the response, also including header lines. The Unique-ID module is calculating a unique identifier for every request. We\u2019ll return to this later on.<\/p>\n We are now ready for a new, comprehensive log format. The format also includes values that the server is as of yet unaware of with the modules defined up to now. It will leave them empty or show them as a hyphen \u201c-\u201d<\/em>. Only with the Logio<\/em> module just enabled this won\u2019t work. The server will crash if we request these values without them being present.<\/p>\n We will gradually be filling in these values in the instructions below. But, as explained above, because it is useful to use the same log format everywhere, we will now be getting a bit ahead of ourselves in the configuration below.<\/p>\n We\u2019ll be starting from the combined<\/em> format and will be extending it to the right. The advantage of this is that the extended log files will continue to be readable in many standard tools, because the additional values are simply ignored. Furthermore, it is very easy to convert the extended log file back into the basic version and then still end up with a combined<\/em> log format.<\/p>\n We define the log format as follows:<\/p>\n The new log format adds 23 values to the access log. This may seem excessive at first glance, but there are in fact good reasons for all of them and having these values available in day-to-day work makes it a lot easier to track down errors.<\/p>\n Let\u2019s have a look at the values in order.<\/p>\n In the description of the common<\/em> log format we saw that the second value, the logname<\/em> entry, displays an unused artifact right after the client IP address. We\u2019ll replace this item in the log file with the country code for the client IP address. This is useful, because this country code is strongly characteristic of an IP address. (In many cases there is a big difference whether the request originates nationally or from the South Pacific). It is now practical to place it right next to the IP address and have it add more in-depth information to the meaningless number.<\/p>\n After this comes the time format defined in Tutorial 2, which is oriented to the time format of the error log and is now congruent with it. We are also keeping track of microseconds, giving us precise timing information. We are familiar with the next values.<\/p>\n _”%Content-Type}i” describes the Content-Type Request header. This is usually empty, however requests with the HTTP method POST that are used to submit forms or upload data make use of this header. We are ultimately planning to add ModSecurity to our service. Together with that module, the information about the content type becomes really important as the behavior of the ModSecurity engine changes a lot depending on this header.<\/p>\n %{remote}p<\/em> is the next addition. It stands for port number of the client. So whenever a client opens a TCP connection to a server address and port, he uses one of his own ports. Information about this port can tell us just how many connections a client opens to our server. And in a situation where multiple clients connect using the same IP address (thanks to Network Address Translation NAT), it can help to tell the clients apart.<\/p>\n %v<\/em> refers to the canonical host name of the server that handled the request. If we talk to the server via an alias, the actual name of the server will be written here, not the alias. In a virtual host setup the virtual host server names are also canonical. They will thus also show up here and we can distinguish among them in the log file.<\/p>\n %A<\/em> is the IP address of the server that received the request. This value helps us to distinguish among servers if multiple log files are combined or multiple servers are writing to the same log file.<\/p>\n %p<\/em> then describes the port number on which the request was received. This is also important to be able to keep some entries apart if we combine different log files (such as those for port 80 and those for port 443).<\/p>\n %R<\/em> shows the handler that generated the response to a request. This value may also be empty (\u201c-\u201c) if a static file was sent. Or it uses proxy<\/em> to indicate that the request was forwarded to another server.<\/p>\n %{BALANCER_WORKER_ROUTE}e<\/em> also has to do with forwarding requests. If we alternate among target servers this value represents where the request was sent.<\/p>\n %X<\/em> shows the status of the TCP connection after the request has been completed. There are three possible values: The connection is closed (–<\/em>), the connection is being kept open using Keep-Alive<\/em> (+<\/em>) or the connection was lost before the request could be completed (X<\/em>).<\/p>\n \u201c%{cookie}n\u201d<\/em> is a value employed by user tracking. This enables us to use a cookie to identify a client and recognize it at a later point in time, provided it still has the cookie. If we set the cookie for the whole domain, e.g.\u00a0to example.com and not limited to www.example.com, then we are even able to track a client across multiple hosts. Ideally, this would also be possible from the client\u2019s IP address, but this may change over the course of a session and multiple clients may be sharing a single IP address.<\/p>\n %{UNIQUE_ID}e<\/em> is a very helpful value. A unique ID is created on the server for every request. When we output this value on an error page for instance, then a request in the log file can be easily identified using a screenshot, and ideally the entire session can be reproduced on the basis of the user tracking cookies.<\/p>\n Now come two values made available by mod_ssl<\/em>. The encryption module provides the log module values in its own name space, indicated by x<\/em>. The individual values are explained in the mod_ssl<\/em> documentation. For the operation of a server the protocol and encryption used are of primary interest. These two values, referenced by %{SSL_PROTOCOL}x<\/em> and <\/a>LogFormat<\/span> "%h %l %u %t <\/span>\\"<\/span>%r<\/span>\\"<\/span> %>s %b"<\/span> common<\/span>\n<\/a>...<\/span><\/span>\n<\/a>CustomLog<\/span> logs\/access.log common<\/span><\/code><\/pre><\/div>\n<\/a>[25\/Nov<\/span>\/2014:08<\/span>:51:22 +0100]<\/span><\/code><\/pre><\/div>\n<\/a>%<\/span>{[%Y-%m-%d %H:%M:%S %z (%s)]}t<\/span><\/span><\/code><\/pre><\/div>\n<\/a>[2014-11-25<\/span> 09:34:33 +0100 (1322210073)]<\/span><\/code><\/pre><\/div>\n<\/a>Method<\/span> URI Protocol<\/span><\/code><\/pre><\/div>\n<\/a>GET<\/span> \/index.html HTTP\/1.1<\/span><\/code><\/pre><\/div>\n<\/a>%<\/span><<\/span>s %><\/span>s<\/span><\/code><\/pre><\/div>\nStep 2: Understanding the combined log format<\/h3>\n
<\/a>LogFormat<\/span> "%h %l %u %t <\/span>\\"<\/span>%r<\/span>\\"<\/span> %>s %b <\/span>\\"<\/span>%{Referer}i<\/span>\\"<\/span> <\/span>\\"<\/span>%{User-Agent}i<\/span>\\"<\/span>"<\/span> combined<\/span>\n<\/a>...<\/span><\/span>\n<\/a>CustomLog<\/span> logs\/access.log combined<\/span><\/code><\/pre><\/div>\nStep 3: Enabling the Logio and Unique-ID modules<\/h3>\n
<\/a>LoadModule<\/span> logio_module modules\/mod_logio.so<\/span>\n<\/a>LoadModule<\/span> unique_id_module modules\/mod_unique_id.so<\/span><\/code><\/pre><\/div>\nStep 4: Configuring the new, extended log format<\/h3>\n
<\/a><\/span>\n<\/a>LogFormat<\/span> "%h %{GEOIP_COUNTRY_CODE}e %u [%{%Y-%m-%d %H:%M:%S}t.%{usec_frac}t] <\/span>\\"<\/span>%r<\/span>\\"<\/span> %>s %b \\<\/span><\/span>\n<\/a>\\"<\/span>%{Referer}i<\/span>\\"<\/span> <\/span>\\"<\/span>%{User-Agent}i<\/span>\\"<\/span> <\/span>\\"<\/span>%{Content-Type}i<\/span>\\"<\/span> %{remote}p %v %A %p %R \\<\/span><\/span>\n<\/a>%{BALANCER_WORKER_ROUTE}e %X <\/span>\\"<\/span>%{cookie}n<\/span>\\"<\/span> %{UNIQUE_ID}e %{SSL_PROTOCOL}x %{SSL_CIPHER}x \\<\/span><\/span>\n<\/a>%I %O %{ratio}n%% %D %{ModSecTimeIn}e %{ApplicationTime}e %{ModSecTimeOut}e \\<\/span><\/span>\n<\/a>%{ModSecAnomalyScoreInPLs}e %{ModSecAnomalyScoreOutPLs}e \\<\/span><\/span>\n<\/a>%{ModSecAnomalyScoreIn}e %{ModSecAnomalyScoreOut}e"<\/span> extended<\/span>\n<\/a><\/span>\n<\/a>...<\/span><\/span>\n<\/a><\/span>\n<\/a>CustomLog<\/span> logs\/access.log extended<\/span><\/code><\/pre><\/div>\nStep 5: Understanding the new, extended log format<\/h3>\n