Access Logging

Nova Nodes can stream HTTP or TCP "access logs" to a syslog server on your network. This may often be a graylog cluster, etc. and can have their format customized but mimic Apache log format files.

TCP vs HTTP access logs

Nova ADCs log in two ways, TCP and HTTP. All ADCs will automatically use TCP logging when access logging is enabled, except for SSL Termination and HTTP ADCs. These will use HTTP logging.

HTTP logging has additional information, and can have additional custom log format flags included. Naturally, it is only available on HTTP/S traffic.

Performance Considerations

Logging can often be seen as the enemy of high performance systems. Nova Nodes can generate hundreds of thousands of log lines per second (one line per request) which can slow the performance of the Node slightly, and also can be very difficult for you (as the client) to consume.

For this reason we also support log sampling - sending only a customizable percentage of the logs. For example a sample value of 5 will send 5 in 100 (or 1 in 20) log lines to your server, selected randomly. This is good for performance analytics, but bad for security and debugging of course.

Log Formats

By default, Nova uses two formats, once for TCP and one for HTTP. You can also customize these to include whatever information is needed.

Default TCP Format

>>> Feb  6 12:12:56 localhost \
      nova[14387]: 10.0.1.2:33313 [06/Feb/2009:12:12:51.443] fnt \
      bck/srv1 0/0/5007 212 -- 0/0/0/0/3 0/0

  Field   Format                                Extract from the example above
      1   process_name '[' pid ']:'                               nova[14387]:
      2   client_ip ':' client_port                             10.0.1.2:33313
      3   '[' accept_date ']'                       [06/Feb/2019:12:12:51.443]
      4   frontend_name                                                    fnt
      5   backend_name '/' server_name                                bck/srv1
      6   Tw '/' Tc '/' Tt*                                           0/0/5007
      7   bytes_read*                                                      212
      8   termination_state                                                 --
      9   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    0/0/0/0/3
     10   srv_queue '/' backend_queue                                      0/0

Default HTTP Format

>>> Feb  6 12:14:14 localhost \
      nova[14389]: 10.0.1.2:33317 [06/Feb/2009:12:14:14.655] http-in \
      static/srv1 10/0/30/69/109 200 2750 - - ---- 1/1/1/1/0 0/0 {nova-adc.com} \
      {} "GET /index.html HTTP/1.1"

  Field   Format                                Extract from the example above
      1   process_name '[' pid ']:'                               nova[14389]:
      2   client_ip ':' client_port                             10.0.1.2:33317
      3   '[' request_date ']'                      [06/Feb/2009:12:14:14.655]
      4   frontend_name                                                http-in
      5   backend_name '/' server_name                             static/srv1
      6   TR '/' Tw '/' Tc '/' Tr '/' Ta*                       10/0/30/69/109
      7   status_code                                                      200
      8   bytes_read*                                                     2750
      9   captured_request_cookie                                            -
     10   captured_response_cookie                                           -
     11   termination_state                                               ----
     12   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    1/1/1/1/0
     13   srv_queue '/' backend_queue                                      0/0
     14   '{' captured_request_headers* '}'                     {nova-adc.com}
     15   '{' captured_response_headers* '}'                                {}
     16   '"' http_request '"'                      "GET /index.html HTTP/1.1"

Custom Formats

Nova ADCs support customizing what is logged (vs the defaults above). We do this using variables that you can use in your log format string.

% precedes log format variables. Variables can take arguments using braces ('{}'), and multiple arguments are separated by commas within the braces. Flags may be added or removed by prefixing them with a '+' or '-' sign.

Special variable "%o" may be used to propagate its flags to all other variables on the same format string. This is particularly handy with quoted ("Q") and escaped ("E") string formats.

Examples

Nova Default TCP Format
%ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq

Nova Default HTTP Format
%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r 

Variables

Below are the available variables.

  +---+------+-----------------------------------------------+-------------+
  | R | var  | field name (8.2.2 and 8.2.3 for description)  | type        |
  +---+------+-----------------------------------------------+-------------+
  |   | %o   | special variable, apply flags on all next var |             |
  +---+------+-----------------------------------------------+-------------+
  |   | %B   | bytes_read           (from server to client)  | numeric     |
  | H | %CC  | captured_request_cookie                       | string      |
  | H | %CS  | captured_response_cookie                      | string      |
  |   | %H   | hostname                                      | string      |
  | H | %HM  | HTTP method (ex: POST)                        | string      |
  | H | %HP  | HTTP request URI without query string (path)  | string      |
  | H | %HQ  | HTTP request URI query string (ex: ?bar=baz)  | string      |
  | H | %HU  | HTTP request URI (ex: /foo?bar=baz)           | string      |
  | H | %HV  | HTTP version (ex: HTTP/1.0)                   | string      |
  |   | %ID  | unique-id                                     | string      |
  |   | %ST  | status_code                                   | numeric     |
  |   | %T   | gmt_date_time                                 | date        |
  |   | %Ta  | Active time of the request (from TR to end)   | numeric     |
  |   | %Tc  | Tc                                            | numeric     |
  |   | %Td  | Td = Tt - (Tq + Tw + Tc + Tr)                 | numeric     |
  |   | %Tl  | local_date_time                               | date        |
  |   | %Th  | connection handshake time (SSL, PROXY proto)  | numeric     |
  | H | %Ti  | idle time before the HTTP request             | numeric     |
  | H | %Tq  | Th + Ti + TR                                  | numeric     |
  | H | %TR  | time to receive the full request from 1st byte| numeric     |
  | H | %Tr  | Tr (response time)                            | numeric     |
  |   | %Ts  | timestamp                                     | numeric     |
  |   | %Tt  | Tt                                            | numeric     |
  |   | %Tw  | Tw                                            | numeric     |
  |   | %U   | bytes_uploaded       (from client to server)  | numeric     |
  |   | %ac  | actconn                                       | numeric     |
  |   | %b   | backend_name                                  | string      |
  |   | %bc  | beconn      (backend concurrent connections)  | numeric     |
  |   | %bi  | backend_source_ip       (connecting address)  | IP          |
  |   | %bp  | backend_source_port     (connecting address)  | numeric     |
  |   | %bq  | backend_queue                                 | numeric     |
  |   | %ci  | client_ip                 (accepted address)  | IP          |
  |   | %cp  | client_port               (accepted address)  | numeric     |
  |   | %f   | frontend_name                                 | string      |
  |   | %fc  | feconn     (frontend concurrent connections)  | numeric     |
  |   | %fi  | frontend_ip              (accepting address)  | IP          |
  |   | %fp  | frontend_port            (accepting address)  | numeric     |
  |   | %ft  | frontend_name_transport ('~' suffix for SSL)  | string      |
  |   | %lc  | frontend_log_counter                          | numeric     |
  |   | %hr  | captured_request_headers default style        | string      |
  |   | %hrl | captured_request_headers CLF style            | string list |
  |   | %hs  | captured_response_headers default style       | string      |
  |   | %hsl | captured_response_headers CLF style           | string list |
  |   | %ms  | accept date milliseconds (left-padded with 0) | numeric     |
  |   | %pid | PID                                           | numeric     |
  | H | %r   | http_request                                  | string      |
  |   | %rc  | retries                                       | numeric     |
  |   | %rt  | request_counter (HTTP req or TCP session)     | numeric     |
  |   | %s   | server_name                                   | string      |
  |   | %sc  | srv_conn     (server concurrent connections)  | numeric     |
  |   | %si  | server_IP                   (target address)  | IP          |
  |   | %sp  | server_port                 (target address)  | numeric     |
  |   | %sq  | srv_queue                                     | numeric     |
  | S | %sslc| ssl_ciphers (ex: AES-SHA)                     | string      |
  | S | %sslv| ssl_version (ex: TLSv1)                       | string      |
  |   | %t   | date_time      (with millisecond resolution)  | date        |
  | H | %tr  | date_time of HTTP request                     | date        |
  | H | %trg | gmt_date_time of start of HTTP request        | date        |
  | H | %trl | local_date_time of start of HTTP request      | date        |
  |   | %ts  | termination_state                             | string      |
  | H | %tsc | termination_state with cookie status          | string      |
  +---+------+-----------------------------------------------+-------------+

    R = Restrictions : H = mode http only ; S = SSL only

Termination State

Nova Vision logs (or streamed access logs) provide a session termination indicator in the "termination_state" field, just before the number of active connections. It is 2-characters long in TCP mode, and is extended to 4 characters in HTTP mode, each of which has a special meaning :

  - On the first character, a code reporting the first event which caused the
    session to terminate :

        C : the TCP session was unexpectedly aborted by the client.

        S : the TCP session was unexpectedly aborted by the server, or the
            server explicitly refused it.

        P : the session was prematurely aborted by the proxy, because of a
            connection limit enforcement, because a DENY filter was matched,
            because of a security check which detected and blocked a dangerous
            error in server response which might have caused information leak
            (e.g. cacheable cookie).

        L : the session was locally processed by Nova and was not passed to
            a server. This is what happens for stats and redirects.

        R : a resource on the proxy has been exhausted (memory, sockets, source
            ports, ...). Usually, this appears during the connection phase, and
            system logs should contain a copy of the precise error. If this
            happens, it must be considered as a very serious anomaly which
            should be fixed as soon as possible by any means.

        I : an internal error was identified by the proxy during a self-check.
            This should NEVER happen, and you are encouraged to report any log
            containing this, because this would almost certainly be a bug. It
            would be wise to preventively restart the process after such an
            event too, in case it would be caused by memory corruption.

        D : the session was killed by Nova because the server was detected
            as down and was configured to kill all connections when going down.

        U : the session was killed by Nova on this backup server because an
            active server was detected as up and was configured to kill all
            backup connections when going up.

        K : the session was actively killed by an admin operating on Nova.

        c : the client-side timeout expired while waiting for the client to
            send or receive data.

        s : the server-side timeout expired while waiting for the server to
            send or receive data.

        - : normal session completion, both the client and the server closed
            with nothing left in the buffers.

  - on the second character, the TCP or HTTP session state when it was closed :

        R : the proxy was waiting for a complete, valid REQUEST from the client
            (HTTP mode only). Nothing was sent to any server.

        Q : the proxy was waiting in the QUEUE for a connection slot. This can
            only happen when servers have a 'maxconn' parameter set. It can
            also happen in the global queue after a redispatch consecutive to
            a failed attempt to connect to a dying server. If no redispatch is
            reported, then no connection attempt was made to any server.

        C : the proxy was waiting for the CONNECTION to establish on the
            server. The server might at most have noticed a connection attempt.

        H : the proxy was waiting for complete, valid response HEADERS from the
            server (HTTP only).

        D : the session was in the DATA phase.

        L : the proxy was still transmitting LAST data to the client while the
            server had already finished. This one is very rare as it can only
            happen when the client dies while receiving the last packets.

        T : the request was tarpitted. It has been held open with the client
            during the whole "timeout tarpit" duration or until the client
            closed, both of which will be reported in the "Tw" timer.

        - : normal session completion after end of data transfer.

  - the third character tells whether the persistence cookie was provided by
    the client (only in HTTP mode) :

        N : the client provided NO cookie. This is usually the case for new
            visitors, so counting the number of occurrences of this flag in the
            logs generally indicate a valid trend for the site frequentation.

        I : the client provided an INVALID cookie matching no known server.
            This might be caused by a recent configuration change, mixed
            cookies between HTTP/HTTPS sites, persistence conditionally
            ignored, or an attack.

        D : the client provided a cookie designating a server which was DOWN,
            so either "option persist" was used and the client was sent to
            this server, or it was not set and the client was redispatched to
            another server.

        V : the client provided a VALID cookie, and was sent to the associated
            server.

        E : the client provided a valid cookie, but with a last date which was
            older than what is allowed by the "maxidle" cookie parameter, so
            the cookie is consider EXPIRED and is ignored. The request will be
            redispatched just as if there was no cookie.

        O : the client provided a valid cookie, but with a first date which was
            older than what is allowed by the "maxlife" cookie parameter, so
            the cookie is consider too OLD and is ignored. The request will be
            redispatched just as if there was no cookie.

        U : a cookie was present but was not used to select the server because
            some other server selection mechanism was used instead (typically a
            "use-server" rule).

        - : does not apply (no cookie set in configuration).

  - the last character reports what operations were performed on the persistence
    cookie returned by the server (only in HTTP mode) :

        N : NO cookie was provided by the server, and none was inserted either.

        I : no cookie was provided by the server, and the proxy INSERTED one.
            Note that in "cookie insert" mode, if the server provides a cookie,
            it will still be overwritten and reported as "I" here.

        U : the proxy UPDATED the last date in the cookie that was presented by
            the client. This can only happen in insert mode with "maxidle". It
            happens every time there is activity at a different date than the
            date indicated in the cookie. If any other change happens, such as
            a redispatch, then the cookie will be marked as inserted instead.

        P : a cookie was PROVIDED by the server and transmitted as-is.

        R : the cookie provided by the server was REWRITTEN by the proxy, which
            happens in "cookie rewrite" or "cookie prefix" modes.

        D : the cookie provided by the server was DELETED by the proxy.

        - : does not apply (no cookie set in configuration).