User’s Guide

Application Requirements

Your application needs to inherit from Recorder to use divák. The Recorder class provides methods to inject observers into the request processing pipeline. The only notable functionality that it provides is to ensure that every request has a divak_request_id attribute that is set to None by default and that the attribute is added to the logging context when writing to tornado.log.access_log. Beyond that, it is a strictly opt-in interface in that you must explicitly add observers to enable functionality.

Request Tracing

Correlation Headers

The simplest form of tracing a request is to pass a header with a correlation ID through the system. The RequestIdPropagator class simply propagates a named header from the request into the response. The default behavior is to relay a request header named Request-ID from request to response. This functionality is enabled by adding a RequestIdPropagator instance to your application by calling add_divak_propagator() as shown below.

examples/request_tracing.py

class MyApplication(divak.api.Recorder, web.Application):

    def __init__(self, *args, **kwargs):
        super(MyApplication, self).__init__(
            [web.url('/status', StatusHandler)],
            *args, **kwargs)
        self.set_divak_service('my-service')
        self.add_divak_propagator(divak.api.RequestIdPropagator())

This simple change will copy the Request-ID header from the request headers to the response headers. Having a HTTP header that is relayed from request to response makes it possible to trace the processing of a request through multiple services provided that you record it somewhere.

Request with header

GET /status HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: 127.0.0.1:8000
Request-ID: a6bd045cdcf64451a076a59bdb367ba6
User-Agent: HTTPie/0.9.9

Response with copied header

HTTP/1.1 200 OK
Content-Length: 61
Content-Type: application/json
Date: Sat, 10 Feb 2018 13:48:41 GMT
Etag: "e3c1480268930c91ab9eb759a1fa5fcad3ab5e28"
Request-Id: a6bd045cdcf64451a076a59bdb367ba6
Server: TornadoServer/4.5.3

{
   "service": "my-service",
   "status": "ok",
   "version": "0.0.0"
}

If the header is not included in the request, then it will generate a UUIDv4 value and insert it into the response. Of course, the value generation function can be overridden to anything you want by passing the value_factory keyword to RequestIdPropagator.

Request without header

GET /status HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: 127.0.0.1:8000
User-Agent: HTTPie/0.9.9

Response with generated header

HTTP/1.1 200 OK
Content-Length: 61
Content-Type: application/json
Date: Sat, 10 Feb 2018 13:52:42 GMT
Etag: "e3c1480268930c91ab9eb759a1fa5fcad3ab5e28"
Request-Id: 31510218-abb2-49b6-bfd3-a036fe4f6113
Server: TornadoServer/4.5.3

{
    "service": "my-service",
    "status": "ok",
    "version": "0.0.0"
}

Request Logging

The divak.api.Recorder class modifies the Python logging module to ensure that you can use %(divak_request_id)s in log formats. It also overrides the log_request() method and outputs something closer to a standard access log line using the following log format:

$REMOTE-IP "$METHOD $URI" $STATUS "$USER-AGENT" $PROCESSING-TIME

For example:

127.0.0.1 "GET /status" 200 "curl/7.54.0" 0.001341104507446289

The $PROCESSING-TIME is in decimal seconds and the user-agent & request id portions both default to "-" if they are missing for some reason. You can modify this behavior by overriding the method in your application class or by adding a custom formatting pattern to tornado.log.access_log. The following dictionary is passed as the extra parameter to the log method:

extra = {
   'remoteip': '127.0.0.1',
   'status': handler.get_status(),
   'elapsed': request.request_time(),
   'method': request.method,
   'uri': request.uri,
   'useragent': request.headers.get('User-Agent', '-'),
   'divak_request_id': getattr(request, 'divak_request_id', '-'),
}

If you want to insert the request ID into the access log, then you should modify the default log format to include it when you initialize the logging module:

examples/request_tracing.py

def main():
    logging.basicConfig(
        level=logging.INFO,
        format=('%(levelname)1.1s - %(name)s: %(message)s '
                '{%(divak_request_id)s}'))
    app = MyApplication(debug=True)
    app.listen(8000)
    ioloop.IOLoop.current().start()

This will include the request ID on every log line that it is available on. The divak.api.Logger mix-in ensures that it is available on it’s self.logger instance. The divak.api.Recorder class inserts the request id into access log entries as well. Access logs entries from the example look like:

127.0.0.1 "GET /status" 200 "curl/7.54.0" 0.001341104507446289 {84DC5B74-752A-468F-A786-806696A5DE01}