Logging in Go Microservices

Good practice to produce efficient cross-services logs
Paris API Meetup #30

Transcript

1. Logging in Microservices Paris API Meetup #30 7 November 2017 Leo Unbekandt CTO at Scalingo
2. What this lightning talk will cover Handling logs in and across Go services Not indexing, aggregating nor ELK-ing → Goal prepare the logs for these (Would love to, but 5 minutes is not enough)
3. Logging is hard Even in one single service. func main() { http.HandleFunc("/", Handler) http.ListenAndServe(":8001", nil) } func Handler(w http.ResponseWriter, r *http.Request) { log.Println("A user is doing something here") } 2017/11/04 11:21:07 A user is doing something here Yay… well, thanks stdlib, super useful.
4. Using a logging middleware func logMiddleware(next http.HandlerFunc) http.HandlerFunc { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { log.Println("Before request", r.URL) before := time.Now() next.ServeHTTP(w, r) duration := time.Now().Sub(before) log.Println("Before request", r.URL, "duration", duration) }) } 2017/11/04 11:21:45 Before request /paris-api 2017/11/04 11:21:45 A user is doing something here 2017/11/04 11:21:45 Before request /paris-api duration 15.793µs Slightly better.
5. Next step is formatted logging func main() { applogger := logrus.New() applogger.Formatter = &logrus.TextFormatter{ TimestampFormat: "2006-01-02T15:04:05.000", FullTimestamp: true, } http.HandleFunc("/", logMiddleware(Handler, applogger)) http.ListenAndServe(":8003", nil) } func logMiddleware(next http.HandlerFunc, logger logrus.FieldLogger) http.HandlerFunc { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { fields := logrus.Fields{ "method": r.Method, "path": r.URL.String(), "from": r.RemoteAddr, } reqlogger := logger.WithFields(fields) reqlogger.Info("starting request") // …
6. Next step is formatted logging // … rw := negroni.NewResponseWriter(w) before := time.Now() next(rw, r) after := time.Now() reqlogger.WithFields(logrus.Fields{ "status": rw.Status(), "duration": after.Sub(before).Seconds(), "bytes": rw.Size(), }).Info("request completed") }) } INFO[TS] starting request from="[::1]:46250" method=GET path="/paris-api" INFO[TS] A user is doing something here INFO[TS] request completed bytes=20 duration=2.3522e-05 from="[::1]:46250" host="localhost:8003" method=GET path="/paris-api" status=200
7. Gather all log lines from a request func RequestIDMiddleware(next http.HandlerFunc) http.HandlerFunc { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { id := r.Header.Get("X-Request-ID") if len(id) == 0 { id = uuid.NewV4().String() r.Header.Set("X-Request-ID", id) } r = r.WithContext(context.WithValue(r.Context(), "request_id", id)) next(w, r) }) } And in the logging middleware: id, ok := r.Context().Value("request_id").(string) if ok { logger = logger.WithField("request_id", id) }
8. Con gure your reverse proxy Most HTTP servers like Nginx, HAProxy, Apache have modules to add a X-Request-ID header. Also builtin in PaaS (Scalingo / Heroku) doc.scalingo.com/internals/x-request-id (http://doc.scalingo.com/internals/x-request-id) devcenter.heroku.com/articles/http-request-id (https://devcenter.heroku.com/articles/http-request-id)
9. Forward this Request-ID req, _ := http.NewRequest("GET", url, nil) reqID, ok := ctx.Value("request_id").(string) if ok && len(reqID) != 0 { req.Header.Set("X-Request-ID", reqID) }
10. Outside HTTP: Message queues Request ID in the metadata of the message: type Message struct { RequestID string `json:"request_id"` Type string `json:"type"` At int64 `json:"at"` Payload json.RawMessage `json:"payload"` }
11. Outside HTTP : Message queue producers func (p *Producer) Produce(ctx context.Context, topic string, message Message) error { reqid, ok := ctx.Value("request_id").(string) if !ok { reqid = uuid.NewV4().String() } message.RequestID = reqid // Really produce message }
12. Outside HTTP : Message queue consumers → Create middlewares to get/add the Request ID from/to the context. func (c *Consumer) Start(ctx context.Context) func() { c.logger = logctx.Get(ctx).WithFields(logrus.Fields{ "topic": c.Topic, "channel": c.Channel, }) for message := range c.in { msgLogger := c.logger.WithFields(logrus.Fields{ "message_id": fmt.Sprintf("%s", message.ID), "message_type": msg.Type, "request_id": msg.RequestID, }) ctx := context.WithValue( context.WithValue( context.Background(), "request_id", msg.RequestID, ), "logger", msgLogger, ) // ... c.Handler(ctx, msg.Type, msg.Payload) } }
13. Summary | End-user request | -> Service 1 -> Service 2 -> Service 3 | *- Message bus (topic: stats) | *--> Service 4 *--> Service 5 INFO[TS] log content1 source=service1 request_id: <reqid> INFO[TS] log content2 source=service2 request_id: <reqid> INFO[TS] log content3 source=service3 request_id: <reqid> INFO[TS] log content4 source=service4 request_id: <reqid> topic=stats channel=ch1 INFO[TS] log content5 source=service5 request_id: <reqid> topic=stats channel=ch2 To Take away: Formatted logs Request ID Shared Request ID across services
14. Thank you Leo Unbekandt CTO at Scalingo @Soulou (http://twitter.com/Soulou)