Logging

Preliminaries

This note describes the options available for fine-grain control over the server's logging operations.

Webmasters need to know what's going on with the server in order to properly fine-tune its operation. One of the most important tools to help with this is the server's log.

Different stages of a website's operation need different information. During development, designers and authors need to know that embedded media and hyperlinked documents are being served without 404 status codes. During initial startup, webmasters need to know that access to the public is allowed, and that access to restricted content is prohibited. When the website begins to receive awareness, and usage patterns begin to be recognized, engineers need to fine tune caching and load balancing. And when the website has reached a steady state, someone needs to monitor what's going on and be alerted when bad actors are behaving maliciously.

The server's logging facility can help with all of these scenarios.

Motivation

The server sends messages to the system log with the intention that they will be read and analyzed by computers rather than people. Messages are designed to be both flexible and parsable. Anyone with basic knowledge of regular expressions and a scripting language should be able to filter the system log to answer these types of questions:

• How many requests were successfully fulfilled yesterday?
• How many megabytes of data were transferred over the network?
• What was the average compression ratio for gzip responses?
• Which IP addresses generated more than ten potentially malicious requests?
• What is the percentage breakdown of user requests by browser type?
• Are there any internal hyperlinks that no longer work?
• Did any unexpected errors occur from the website's custom pages?

SystemD

When operated under control of the SystemD service manager, messages are routed to the system log. When running in direct foreground mode, messages are sent to the console via STDOUT (this is uncommon).

The server's logging section consists of several subsections allowing for both high-level and fine-tuned configuration:

The message-type subsection comprises seven "on" or "off" switches to enable or disable logging at a high-level.

• request comprises entries that define which HTTP/2 request headers should be logged.
• staging comprises entries that define which of the server's work order variables should be logged.
• information comprises entries that define which server information headers should be logged.
• response comprises entries that define which HTTP/2 response headers should be logged.
• policy comprises entries received from feature policy and content-security policies.
• network enables/disables the logging of TLS network errors.
• cluster enables/disables the logging of startup and shutdown of cluster worker threads.
• debug enables/disables the logging of internal tracing messages.

Message type

The server emits 12 types of messages:

1. Request header entries provide details of each incoming HTTP/2 request.
2. Staging variable entries provide details of about the internal state of the server during the request-response cycle.
3. Information header entries are emitted for responses that contain any of the special server headers that begin with the letters "rw-".
4. Response header entries provide details of each outgoing HTTP/2 response.
5. Policy messages are sent by the browser back to the server in response to unmet policy conditions.
6. Network messages are emitted for TLS network errors such as: no shared cipher, unknown protocol, http request, version too low, wrong version number, and others.
7. Cluster messages are emitted when a worker thread is created or disconnected.
8. Debug messages are used for tracing the path of the request/response cycle through the software.
9. Config messages are emitted during server initialization to show its progress towards binding to the network interface, and to report any non-recoverable configuration mistakes.
10. Error messages are emitted any time an unexpected condition occurs, due to user configuration issues or server software bugs.
11. Nodejs messages are emitted any time an uncaught Node.js exception is thrown.
12. Systemd messages are emitted by the operating system when the server starts or stops.

The content and format of request, staging, information, response and policy messages are configurable. The choice of which header values and variables to be included is made in the logging section.

The network, cluster and debug messages may be enabled or disabled, but the individual messages themselves are non-configurable.

The config, error, nodejs and systemd messages cannot be disabled.

Log message structure

Here is the breakdown of a standard log entry. First there is a message type, as explained above. This is followed by a request-response (RR) identifier, which is a sequential number that is shared by the request/staging/information/response messages of a single RR. This is followed by a series of fields, either HTTP headers or work-order variables.

This is the regular expression for messages generated by the server, where the second parenthesis will capture the fields:

RR=(.*);( .*=.*;)*
						

When sent to the system log via the SystemD service manager, each message is stored with these additional OS-provided values: 1) timestamp, 2) hostname, 3) unit name, and 4) process identifier.

Filtering fields

Many HTTP headers are repetitious and of little value to typical website analysis. The server's configuration can specify exactly which fields to include in the logged message. Each of the four configurable subsections comprise a list of fields to include. When specified this way, only those fields are included; any other HTTP header names or work-order variables will be omitted.

Sometimes, a webmaster may not know which header fields to expect in a message. In that case it is possible to use the special field name 'default', in a configuration subsection, either by itself or immediately after the other field entries. The 'default' keyword is a catch-all fallback; it instructs the server to include any other HTTP header actually present in the logged message. This is a useful technique when setting up a web server the first time, and when learning about HTTP requests and responses. Later, it is more prudent to remove the 'default' catch-all and limit the logging to just what's needed.

Abbreviating field names

In the interest of conserving disk space, it is desirable to shorten fields which may be lengthy both because the HTTP header name itself may be long and because its associated value may be long.

Each configuration entry may include an *abbr attribute which will be substituted for the field name. Typically these abbreviations are 2, 3, or 4 capitalized letters. Be sure to choose unique values in order to retain the ability to parse messages using scripts.

When the *abbr attribute value is "none" or omitted, the full field name is used in the log message.

Here are some typical configuration entries showing the use of the *abbr attribute:

Formatting fields

Some header values can be quite lengthy. These can be shortened using ellipses. Use the *format attribute to instruct the server how much to shorten the string and where to put the ellipsis. There are three meaningful definition patterns: 1) trim leading, 2) trim trailing, and 3) trim middle. Each definition consists of the number of leading characters to keep, followed by three FULL-STOPS, followed by the number of trailing characters to keep.

Given an example header value like this "AaBbCcDdEeFfGgHhIiJjKkLlMmNnOoPpQqRrSsTtUuVvWwXxYyZz" the text to be sent to the log message is demonstrated here:

Be sure to enclose the attribute value in APOSTROPHES.

cookie     *abbr=CO *format='...10'
referer    *abbr=RF *format='10...'
user-agent *abbr=UA *format='8...8'
							

When no format attribute is provided, the default for most field names is *format='20...20'. The exceptions to this rule are the :path and referer fields, which by default use an implicit *format='100...100'. These two special fields retain more of the original string in order to provide better results with the Analytics CLI.

Coloring fields

The foreground and background color of each header value can be set by specifying *fg and *bg attributes. Eight colors are allowed: black, white, red, green, blue, cyan, magenta, and yellow.

cookie     *abbr=CO *fg=red   *bg=white
referer    *abbr=RF *fg=green *bg=black
user-agent *abbr=UA *fg=black *bg=cyan
							

Colors are normally suppressed by the journalctl utility. To enable colors, use the --output=cat switch, like this:

journalctl -u rwserve --output=cat        
						

Orientation of log fields

Log messages are normally sent to the console as single horizontal lines. It is also possible to configure the server to create messages in a vertically stacked style. This is convenient during development and testing, to bring an extra bit of clarity to the output. Do this by adding an orientation vertical setting to the logging section.

Cookbook

server {
    logging {
        message-type {
            request         off
            staging         off
            information     off
            response        off
            network         off
            cluster         off
        }
    }
}
								

server {
    logging {
        message-type {
            request         on
            staging         off
            information     off
            response        on
            network         off
            cluster         off
        }
        request {
            :method           *abbr=ME
            :path             *abbr=PA
            cookie            *abbr=CO
            referer           *abbr=RF
        }
        response {
            :status           *abbr=ST
            content-length    *abbr=CL
            content-type      *abbr=CT
            set-cookie        *abbr=SC
        }
    }
}
								

server {
    logging {
        message-type {
            request         on
            staging         on
            information     off
            response        on
            network         on
            cluster         off
        }
        request {
            default               *format='64...'
        }
        staging {
            remote-address                *abbr=RA
            cookie-map                    *abbr=CM
            parameter-map                 *abbr=PM
            form-data-map                 *abbr=FDM
            user-agent-common-name        *abbr=UACN
            user-agent-groups             *abbr=UAG
            masked-replacement-path       *abbr=MRP
            resource-path                 *abbr=RP
            query-string                  *abbr=QS
            push-candidate                *abbr=PC
            proxy-location                *abbr=PL
            default
        }
        response {
            default               *format='64...'
        }
    }
}
								

server {
    logging {
        message-type {
            request         on
            staging         off
            information     on
            response        on
            network         off
            cluster         off
        }
        request {
            :method           *abbr=ME
            :path             *abbr=PA
            cookie            *abbr=CO
            referer           *abbr=RF
        }
        information {
            default           *format='32...32'
        }
        response {
            :status           *abbr=ST
            content-length    *abbr=CL
            content-type      *abbr=CT
            set-cookie        *abbr=SC
        }
    }
}
								

server {
    logging {
        orientation vertical
        message-type {
            request         on
            staging         off
            information     on
            response        on
            network         off
            cluster         off
        }
        request {
            default           *format='32...32'
        }
        information {
            default           *format='32...32'
        }
        response {
            default           *format='32...32'
        }
    }
}