Spray Routils

Access Logging

In order to accurately log all access to a Spray Server you need to,

Time and log the completion of your routes (Mathias tells me how)
Ensure Routes that throw exceptions have their access logged consistently with routes that do not
Handle timeouts. (Spray Timeout Handling) doesn't allow you to disambiguate the timeout event and the completion of the timedout route. see this Google Groups Discussion for background)

The LogAccessRouting Spray Routing trait takes care of all of these access logging edge cases.

Included is a demo that you can use to test this behaviour. It runs from within sbt using sbt-revolver and uses a custom logger based on a suffix of the Common Log Format. (There are also automated integration tests of the same behaviour.)

Demo a Server that responds within the timeout

reStart 1000 500 will start a server with a request-timeout of 1000ms and a sleep before responding of 500ms. Going to http://localhost:8085/hello will print,

spray-routils "GET /hello HTTP/1.1" 200 12 580

Demo a Server that times out before responding

reStart 500 1000 will start a server with a request-timeout of 500ms and a sleep before responding of 1000ms. Going to http://localhost:8085/hello will print,

spray-routils "GET /hello HTTP/1.1" 500 69 500

It will also cause a dead letter warning to be created because the response handling actor will shutdown on timeout and not receive any message received from the timedout request completing

Demo a Server with a route that always throws an exception

reStart exception and going to http://localhost:8085/hello will print,

spray-routils java.lang.Exception: Test Exception
spray-routils [...]
spray-routils "GET /hello HTTP/1.1" 500 35 125"

Demo a Server with a route that always fails with an Exception

reStart fail and going to http://localhost:8085/hello will print,

spray-routils 	There was an internal server error.: Test Exception
spray-routils 	Completing with '500 Internal Server Error' response
spray-routils "GET /hello HTTP/1.1" 500 35 125"

Including Access Logging in your own Spray Routes

Below is an example snippet showing how you might mix the trait into your own project

import org.caoilte.spray.routing.LogAccessRoutingActor
import org.caoilte.spray.routing.AccessLogger

class YourAccessLogger extends AccessLogger {
  override def logAccess(request: HttpRequest, response: HttpResponse, time: Long) = ???
    
  override def accessAlreadyLogged(request: HttpRequest, response: HttpResponse, time: Long) = ???
}

class YourHttpService extends LogAccessRoutingActor with Actor {
  val accessLogger:AccessLogger = new YourAccessLogger
}

You also need to make sure that you set a request timeout correctly

spray.can {
  server {
    routils-request-timeout = 5 s
    request-timeout = infinite
  }
}

The rather convoluted configuration is necessary in order to implement our own timeout handling instead of relying on Spray's. When a request completes it is impossible to tell if Spray has already timed out the request. This could lead to a request being access logged as completed when in fact its response was discarded. By implementing our own timeout logic we can link Timeouts to normal requests and stop Access Log messages from being generated by timed out requests.

caoilte / spray-routils 0.4.0