Logging in Go Microservices

D2781d29cecddfee7a6f2fbdd4662882?s=47 Soulou
November 07, 2017

Logging in Go Microservices

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

D2781d29cecddfee7a6f2fbdd4662882?s=128

Soulou

November 07, 2017
Tweet

Transcript

  1. 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)
  2. 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.
  3. 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.
  4. 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") // …
  5. 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
  6. 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) }
  7. 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)
  8. 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) }
  9. 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"` }
  10. 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 }
  11. 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) } }
  12. 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
  13. 15.