Access Logging

The Vespa access log format allows the logs to be processed by a number of available tools handling JSON based (log) files. With the ability to add custom key/value pairs to the log from any Searcher, you can easily track the decisions done by container components for given requests.

Vespa Access Log Format

In the Vespa access log, each log event is logged as a JSON object on a single line. The log format defines a list of fields that can be logged with every request. In addition to these fields, custom key/value pairs can be logged via Searcher code. Pre-defined fields:

NameTypeDescriptionAlways present
ipstringThe IP address request came fromyes
timenumberUNIX timestamp with millisecond decimal precision (e.g. 1477828938.123) when request is receivedyes
durationnumberThe duration of the request in seconds with millisecond decimal precision (e.g. 0.123)yes
responsesizenumberThe size of the response in bytesyes
codenumberThe HTTP status code returnedyes
methodstringThe HTTP method used (e.g. 'GET')yes
uristringThe request URI from path and beyond (e.g. '/search?query=test')yes
versionstringThe HTTP version (e.g. 'HTTP/1.1')yes
agentstringThe user agent specified in the requestyes
hoststringThe host header provided in the requestyes
schemestringThe scheme of the requestyes
portnumberThe IP port number of the interface on which the request was receivedyes
remoteaddrstringThe IP address of the remote client if specified in HTTP headerno
remoteportstringThe port used from the remote client if specified in HTTP header no
peeraddrstringAddress of immediate client making request if different from remoteaddrno
peerportstringPort used by immediate client making request if different from remoteportno
user-principalstringThe name of the authenticated user (java.security.Principal.getName()) if principal is setno
ssl-principalstringThe name of the x500 principal if client is authenticated through SSL/TLSno
searchobjectObject holding search specific fieldsno
search.totalhitsnumberThe total number of hits for the queryno
search.hitsnumberThe hits returned in this specific responseno
search.coverageobjectObject holding query coverage information similar to that returned in result set.no
connectionstringReference to the connection log entry. See Connection logno
attributesobjectObject holding custom key/value pairs logged in searcher.no

An example log line will look like this (here, pretty-printed):

{
  "ip": "152.200.54.243",
  "time": 920880005.023,
  "duration": 0.122,
  "responsesize": 9875,
  "code": 200,
  "method": "GET",
  "uri": "/search?query=test&param=value",
  "version": "HTTP/1.1",
  "agent": "Mozilla/4.05 [en] (Win95; I)",
  "host": "localhost",
  "search": {
    "totalhits": 1234,
    "hits": 0,
    "coverage": {
      "coverage": 98,
      "documents": 100,
      "degraded": {
        "non-ideal-state": true
      }
    }
  }
}

Example: Decompress, pretty-print, with human-readable timestamps:

$ jq '. + {iso8601date:(.time | todateiso8601)}' \
  <(unzstd -c /opt/vespa/logs/vespa/access/JsonAccessLog.default.20210601010000.zst)

Logging Remote Address/Port

In some cases when a request passes through an intermediate service, this service may add HTTP headers indicating the IP address and port of the real origin client. These values are logged as remoteaddr and remoteport respectively. Vespa will log the contents in any of the following HTTP request headers as remoteaddr: X-Forwarded-For, Y-RA, YahooRemoteIP or Client-IP. If more than one of these headers are present, the precedence is in the order listed here, i.e. X-Forwarded-For takes precedence over Y-RA. The contents of the Y-RP HTTP request header will be logged as remoteport.

If the remote address or -port differs from those initiating the HTTP request, the address and port for the immediate client making the request are logged as peeraddress and peerport respectively.

Configuring Logging

For details on the access logging configuration see accesslog in the container element in services.xml.

File name pattern

The file name pattern is expanded using the time when the file is created. The following parts in the file name are expanded:

FieldFormatMeaningExample
%YYYYYYear2003
%mMMMonth, numeric08
%xMMMMonth, textualAug
%dddDate25
%HHHHour14
%MmmMinute30
%SssSeconds35
%sSSSMilliseconds123
%ZZTime zone-0400
%TLongSystem.currentTimeMillis1349333576093
%%%Escape percentage%

Log rotation

Apache httpd style log rotation can be configured by setting the rotationScheme. There's two alternatives for the rotationScheme, sequence and date. The rotation time is controlled by setting rotationInterval.

Sequence rotation scheme

The fileNamePattern is used for the active log file name (which in this case will often be a constant string). At rotation, this file is given the name fileNamePattern.N where N is 1 + the largest integer found by extracting the integers from all files ending by .<Integer> in the same directory

<accesslog type='json'
           fileNamePattern='logs/vespa/access/JsonAccessLog.<container id>.%Y%m%d%H%M%S'
           rotationScheme='sequence' />

Date rotation scheme

The fileNamePattern is used for the active log file name here too, but the log files are not renamed at rotation. Instead, you must specify a time-dependent fileNamePattern so that each time a new log file is created, the name is unique. In addition, a symlink is created pointing to the active log file. The name of the symlink is specified using symlinkName.

<accesslog type='json'
           fileNamePattern='logs/vespa/access/JsonAccessLog.<container id>.%Y%m%d%H%M%S'
           rotationScheme='date'
           symlinkName='JsonAccessLog' />

Rotation interval

The time of rotation is controlled by setting rotationInterval:

<accesslog type='json'
           fileNamePattern='logs/vespa/access/JsonAccessLog.<container id>.%Y%m%d%H%M%S'
           rotationInterval='0 60 ...'
           rotationScheme='date'
           symlinkName='JsonAccessLog.<container id>' />

The rotationInterval is a list of numbers specifying when to do rotation. Each element represents the number of minutes since midnight. Ending the list with '...' means continuing the arithmetic progression defined by the two last numbers for the rest of the day. E.g. "0 100 240 480 ..." is expanded to "0 100 240 480 720 960 1200"

Log retention

Access logs are rotated, but not deleted by Vespa processes. It is up to the application owner to take care of archiving of access logs.

Logging Key/Value pairs to the JSON Access Log from Searchers

To add a key/value pair to the access log from a searcher, use

query/result.getContext(true).logValue(key,value)

Such key/value pairs may be added from any thread participating in handling the query without incurring synchronization overhead.

If the same key is logged multiple times, the values written will be included in the log as an array of strings rather than a single string value.

The key/value pairs are added to the attributes object in the log.

An example log line will then look something like this:

{"ip":"152.200.54.243","time":920880005.023,"duration":0.122,"responsesize":9875,"code":200,"method":"GET","uri":"/search?query=test&param=value","version":"HTTP/1.1","agent":"Mozilla/4.05 [en] (Win95; I)","host":"localhost","search":{"totalhits":1234,"hits":0},"attributes":{"singlevalue":"value1","multivalue":["value2","value3"]}}

A pretty print version of the same example:

{
  "ip": "152.200.54.243",
  "time": 920880005.023,
  "duration": 0.122,
  "responsesize": 9875,
  "code": 200,
  "method": "GET",
  "uri": "/search?query=test&param=value",
  "version": "HTTP/1.1",
  "agent": "Mozilla/4.05 [en] (Win95; I)",
  "host": "localhost",
  "search": {
    "totalhits": 1234,
    "hits": 0
  },
  "attributes": {
    "singlevalue": "value1",
    "multivalue": [
      "value2",
      "value3"
    ]
  }
}

Connection log

In addition to the access log, one entry per connection is written to the connection log. This entry is written on connection close. Available fields:

NameTypeDescriptionAlways present
idstringUnique ID of the connection, referenced from access log.yes
timestampnumberTimestamp (ISO8601 format) when the connection was openedyes
durationnumberThe duration of the request in seconds with millisecond decimal precision (e.g. 0.123)yes
peerAddressstringIP address used by immediate client making requestyes
peerPortnumberPort used by immediate client making requestyes
localAddressstringThe local IP address the request was received onyes
localPortnumberThe local port the request was received onyes
remoteAddressstringOriginal client ip, if proxy protocol enabledno
remotePortnumberOriginal client port, if proxy protocol enabledno
httpBytesReceivednumberNumber of HTTP bytes sent over the connectionno
httpBytesSentnumberNumber of HTTP bytes received over the connectionno
requestsnumberNumber of requests sent by the clientno
responsesnumberNumber of responses sent to the clientno
sslobjectDetailed information on ssl connectionno

SSL information

NameTypeDescriptionAlways present
clientSubjectstringClient certificate subjectno
clientNotBeforestringClient certificate valid fromno
clientNotAfterstringClient certificate valid tono
sessionIdstringSSL session idno
protocolstringSSL protocolno
cipherSuitestringName of session cipher suiteno
sniServerNamestringSNI server nameno