Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Logging in Go Microservices

Soulou
November 07, 2017

Logging in Go Microservices

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

Soulou

November 07, 2017
Tweet

More Decks by Soulou

Other Decks in Programming

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