Recently while working on the open source EdgeX Foundry project, I had the requirement to implement a simple service tracing mechanism whereby a correlation ID originated by a calling application could be handed from one service to the next as the request was fulfilled. EdgeX Foundry uses a microservice architecture and tracing of service interaction is a basic requirement of such, so I was pleased to work on adding this capability. I had previously implemented a similar solution in a .NET environment but was a little unsure about how this could be accomplished using Go.
The project was already using Gorilla MUX as its API router, albeit a somewhat outdated version. I’d heard quite a lot about GoKit and took that for a spin. Its approach to middleware seemed to fit my need quite well, but I was concerned that I might need to take on the rest of the framework and there wasn’t time to convert all of the EdgeX services. Plus I wasn’t willing to undergo a re-architecture in order to obtain the single request interception feature. I returned to look closer at whether upgrading Gorilla MUX might be a solution. Sure enough, with the v1.6.1 release they had added first class support for middleware. I locally upgraded our dependency on Gorilla MUX to v1.7.0 and went about seeing if I could make this work.
For the remainder of the post, I’d like to walk through the current solution as used by the EdgeX Foundry project. There are three functions, each of which corresponds to the GorillaMUX MiddlewareFunc type.
// MiddlewareFunc is a function which receives an http.Handler and returns another http.Handler.
// Typically, the returned handler is a closure which does something with the http.ResponseWriter and http.Request passed
// to it, and then calls the handler passed as parameter to the MiddlewareFunc.
type MiddlewareFunc func(http.Handler) http.HandlerEach EdgeX microservice has a router.go with a LoadRestRoutes() function in which all handlers are wired up. We want request interception to happen on all of the routes in a given service. After all, the purpose of the correlation ID is to track every service interaction — whether the request comes from another service within EdgeX, a third party service or some other unexpected caller. As part of the interception, we need to accomplish the following:
- Check to see if the correlation-id HTTP header has been included with the incoming request.
- If so, obtain the value and add it to the request’s context.
- If not, create the value and add it to the request’s context
- Log a statement when the request begins showing the correlation ID value and the path being called.
- Log a statement when the request completes showing the correlation ID value and the time taken to complete handling of the request.
Once all of the handlers servicing the primary functionality of the API have been registered, it’s time to enable our interception. At the very bottom of the LoadRestRoutes function, we do the following:
r.Use(correlation.ManageHeader)
r.Use(correlation.OnResponseComplete)
r.Use(correlation.OnRequestBegin)
This will effectively create a chained stack of request handlers. The actual business logic handler will be at the bottom of the stack with these three on top of it. The technique of chaining the handlers together allows for interception both at the beginning and the end of handling the request. For an example of this, let’s take a look at the OnResponseComplete handler
func OnResponseComplete(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
begin := time.Now()
next.ServeHTTP(w, r)
correlationId := FromContext(r.Context())
if LoggingClient != nil {
LoggingClient.Info("Response complete", clients.CorrelationHeader, correlationId, internal.LogDurationKey, time.Since(begin).String())
}
})
}The http.Handler passed into the next parameter is OnRequestBegin, the third item in the stack above. This function itself returns a handler to the MUX. During execution, the ResponseWriter and the Request are passed in from the previous handler, ManageHeader. A local variable “begin” is set to record the time at which we began processing the request. After that, a call to next.ServeHTTP is invoked. This causes OnRequestBegin to be called which itself calls the business logic handler.
Assuming all goes well with the business logic, the stack will unwrap back through OnRequestBegin and on into OnResponseComplete. We now continue by fetching the correlation ID from the context and writing a log statement that shows how long this particular service call took to execute. To illustrate, here’s an actual sample of logging output showing one service calling another in EdgeX Foundry.
level=INFO ts=2019-03-16T22:15:31.697078Z app=edgex-core-data source=middleware.go:43 correlation-id=64b1efbd-d11c-4932-b2cf-cb87d24d691f path=/api/v1/event msg="Begin request"
level=INFO ts=2019-03-16T22:15:31.698833Z app=edgex-core-data source=router.go:217 msg="Posting Event: {\"device\":\"livingroomthermostatdevice\",\"origin\":1471806386919,\"readings\":[{\"origin\":1471806386919,\"name\":\"luminousIntensity1\",\"value\":\"40\"}]}"
level=INFO ts=2019-03-16T22:15:31.70125Z app=edgex-core-metadata source=middleware.go:43 correlation-id=64b1efbd-d11c-4932-b2cf-cb87d24d691f path=/api/v1/device/check/livingroomthermostatdevice msg="Begin request"
level=ERROR ts=2019-03-16T22:15:31.702627Z app=edgex-core-metadata source=rest_device.go:442 msg="Invalid object ID"
level=INFO ts=2019-03-16T22:15:31.702973Z app=edgex-core-metadata source=middleware.go:34 correlation-id=64b1efbd-d11c-4932-b2cf-cb87d24d691f duration=1.723597ms msg="Response complete"
level=ERROR ts=2019-03-16T22:15:31.703763Z app=edgex-core-data source=router.go:229 msg="400 - Invalid object ID\n"
level=INFO ts=2019-03-16T22:15:31.70408Z app=edgex-core-data source=middleware.go:34 correlation-id=64b1efbd-d11c-4932-b2cf-cb87d24d691f duration=7.00305ms msg="Response complete"
- You can see at first the request begins in the core-data service, the correlation ID is shown and the source of the logging statement is “middleware.go”.
- From there, the business logic takes over (notice “source=router.go”) and a call to the core-metadata service is made.
- Next the core-metadata service logs its own “Begin request” message and the correlation ID is the same as the one logged from core-data.
- Core-metadata encounters an ERROR and logs it.
- The response from core-metadata is intercepted and the duration is logged.
- Core-data has received the ERROR from core-metadata and logs the fact.
- Finally, core-data’s response is intercepted and the duration is logged.
Notice that the duration logged by core-data includes the duration of its call to core-metadata. In this way, by searching logs for a given correlation ID the entire call stack of a service to service interaction can be viewed. You will know the overall duration for processing a request, as well as the duration of each individual sub-request that may happen.
I hope this provides some clarity into how middleware within Gorilla MUX can be used to intercept your request/response pipeline. The interface is very modular allowing for easy extension as your requirements grow. For example, you may have noticed that in our pipeline there is currently no middleware handler for authentication. But this could very easily be dropped in between ManageHeader and OnResponseComplete whereby we check credentials and then abort processing if they are absent or invalid. And we can still include the correlation ID as part of our logging.
One last thing I’ll mention here is that our logging is currently based on the Go-Kit logging package. It is very easy to integrate with and provides easily manageable key/value formatting for log entries.
