Logging Every Request of a Go-Kit Service
Writing distributed services in Go is made easier through the use of go-kit. If you haven’t already used go-kit, I definitely recommend checking it out. You can learn most of the basics by working through this example. For this post, you basically need to understand that go-kit offers the ability to break up the construction of services into 3 main layers: transport, endpoint, and service. These layers provide the ability to easily wrap implementations using the middleware or decorator pattern.
Logging is very important. It can be critical in diagnosing problems, tracking functionality, etc. With go-kit services every request follows the flow: transport layer (grpc, http, etc) -> endpoint layer -> service layer. At the service layer each method has a unique signature so creating a middleware to wrap a service layer requires implementing each method of the service interface within the middleware. At the endpoint layer all endpoints use the consistent endpoint type. This means that creating a middleware to wrap endpoints can be done with just one function. So logging of every request can be accomplished by creating a single function. For example (source):
// LoggingMiddleware returns an endpoint middleware that logs the
// duration of each invocation, and the resulting error, if any.
func LoggingMiddleware(logger log.Logger) endpoint.Middleware {
return func(next endpoint.Endpoint) endpoint.Endpoint {
return func(ctx context.Context, request interface{}) (response interface{}, err error) {
defer func(begin time.Time) {
logger.Log("transport_error", err, "took", time.Since(begin))
}(time.Now())
return next(ctx, request) }
}
}
For those of you not familiar with go-kit, this may look a little bit confusing. Basically what is happening is that the LoggingMiddleware function returns a function which takes in an endpoint and returns an endpoint. This allows for some logic to be added before or after the received next endpoint is executed. In this case, a defer is added to call logger.Log which will write to a log 2 things: (1) if an error occurred and (2) how long it took for next to execute. The name of the endpoint is generally placed into the logger before it is passed to LoggingMiddleware like this:
sumEndpoint = LoggingMiddleware(log.With(logger, "method", "Sum"))(sumEndpoint)Problem
The problem with this logging middleware is that there is no request specific information (like the parameters contained within the request and response objects) being logged. This is due to the fact that the endpoint.Endpoint type contains both the request and response objects as type interface{}. Meaning it is impossible to access field values within the request/response without using a type assertion. This gets real messy as you start to add more request/response types (maybe 1 per each of 20 endpoints).
Logs don’t seem very useful to me if all they provide is the name of an endpoint, the execution time for the request, and whether or not an error occurred. This information is useful, but not complete.
Solution
To solve this problem I have created a simple package called eplogger.
Eplogger provides a simple way to get values that are important for logging in the endpoint middleware. This accomplished by implementing an interface on all request/response types that you want to have logged. This interface allows for a single type assertion to be performed on the request/response objects within the eplogger middleware to retrieve the fields that should be logged. It allows for you as a developer to define exactly which request/response fields should be logged, as well as, how they should be logged. Here is the interface:
type AppendKeyvalser interface {
AppendKeyvals(keyvals []interface{}) []interface{}
}Example
Here is an example of a request type with the AppendKeyvalser interface implemented:
SumRequest struct {
A, B int
} func (s SumRequest) AppendKeyvals(keyvals []interface{}) []interface{} {
return append(keyvals, "SumRequest.A", s.A, "SumRequest.B", s.B)
}
The interface is implemented simply by adding in key/value pairs into the received keyvals object using append. You can add a value of any type that implements the fmt.Stringer interface into keyvals and it will be properly logged.
With my request type implementing the AppendKeyvalser interface, this is what logging would look like for every request that hits the Sum endpoint:
level=info method=Sum transport_error=null took=4.071µs SumRequest.A=2 SumRequest.B=3Notice that there is no information in the log about the response object. To add this information, simply implement the AppendKeyvalser interface on the response type:
type SumResponse struct {
V int `json:"v"`
Err error `json:"-"`
}func (s SumResponse) AppendKeyvals(keyvals []interface{}) []interface{} {
return append(keyvals,
"SumResponse.R", s.V, "SumResponse.Err", s.Err)
}
Now logging will contain information about both the request and response objects:
level=info method=Sum transport_error=null took=4.071µs SumRequest.A=2 SumRequest.B=3 SumResponse.R=5 SumResponse.Err=nullThe logging middleware that I created does not care if the request and response objects implement the AppendKeyvalser interface. It adds the logging context if the interface is implemented. Doesn’t add logging context if the interface is not implemented. Works great both ways.
Please try it out and let me know if you have any questions or suggestions!
