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
   

   View Slide

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)
   

   View Slide

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.
   

   View Slide

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.
   

   View Slide

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")
   // …
   

   View Slide

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
   

   View Slide

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)
   }
   

   View Slide

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)
   

   View Slide

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)
   }
   

   View Slide

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"`
    }
    

    View Slide

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
    }
    

    View Slide

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)
    }
    }
    

    View Slide

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:
    INFO[TS] log content2 source=service2 request_id:
    INFO[TS] log content3 source=service3 request_id:
    INFO[TS] log content4 source=service4 request_id: topic=stats channel=ch1
    INFO[TS] log content5 source=service5 request_id: topic=stats channel=ch2
    To Take away:
    Formatted logs
    Request ID
    Shared Request ID across services
    

    View Slide

14. Thank you
    Leo Unbekandt
    CTO at Scalingo
    @Soulou (http://twitter.com/Soulou)
    

    View Slide

15. View Slide