Распределенная трассировка в Go при помощи Jaeger

20 февраля 2019

Типичная проблема, возникающая при разработке распределенных систем, состоит в следующем. Допустим, пользователь посылает системе запрос, и запрос этот обрабатывался очень долго. При этом внутри системы запрос распался на запросы к нескольким внутренним микросервисам, которые в свою очередь могли также превратиться в несколько подзапросов, возможно, даже выполняемых параллельно. Как в такой ситуации выяснить, где тормозит система? Метрики не дают ответа на данный вопрос, поскольку в целом вся система работает нормально, затупил только отдельный запрос конкретного пользователя. Логи могут дать ответ, но они разбросаны по множеству машин, время на которых не синхронизировано. На помощь приходит Jaeger.

Jaeger (читается «егерь») представляет собой сервис для сбора и отображения трейсов в распределенных системах. В рамках этого поста мы не будем рассматривать установку и настройку Jaeger. Во-первых, потому что получится пересказ документации, а во-вторых, потому что вариантов настройки несколько. Например, в качестве бэкенда для хранения данных может быть использована Cassandra или ElasticSearch.

Вместо этого мы запустим Jaeger в Docker-контейнере:

sudo docker run --rm --name jaeger \
  -p 6831:6831/udp -p 16686:16686 jaegertracing/all-in-one:1.8

При этом Jaeger будет хранить данные в памяти. После остановки контейнера они будут утеряны. В принципе, если вас такой вариант устраивает, данный контейнер можно запустить и в бою:

sudo docker run -d --restart=always --name jaeger \
  -p 6831:6831/udp -p 16686:16686 jaegertracing/all-in-one:1.8

Теперь напишем небольшое приложение на языке Go, отправляющее трейсы в Jaeger. В качестве клиентской библиотеки воспользуемся OpenCensus. Начнем с небольшой вспомогательной процедуры:

package utils

import (
  "go.opencensus.io/exporter/jaeger"
  "go.opencensus.io/trace"
)

func InitJaeger(serviceName string) {
  exporter, err := jaeger.NewExporter(jaeger.Options{
    AgentEndpoint: "localhost:6831",
    Process: jaeger.Process{
      ServiceName: serviceName,
      Tags: []jaeger.Tag{
        jaeger.StringTag("hostname", "localhost"),
      },
    },
  })
  if err != nil {
    return
  }
  trace.RegisterExporter(exporter)
  trace.ApplyConfig(trace.Config{
    DefaultSampler: trace.AlwaysSample(),
  })
}

Здесь мы указываем имя нашего приложения, где искать Jaeger, кое-какие дополнительные тэги, и говорим слать трейсы вообще всегда (trace.AlwaysSample()). Кстати, трейсы отправляются по UDP.

Демонстрационное приложение будет состоять из двух частей — HTTP-клиента и HTTP-сервера. При этом клиент как-то должен сообщить серверу, в каком контексте происходит обращение к нему. В общем, чтобы в итоге Jaeger увидел один трейс, несмотря на то, что выполнение кода происходит в двух совершенно независимых программах.

Код клиента:

package main

import (
  "context"
  "encoding/json"
  "fmt"
  "io/ioutil"
  "log"
  "net/http"
  "time"
  "go.opencensus.io/trace"
  "github.com/afiskon/golang-jaeger-example"
)

func main() {
  utils.InitJaeger("client")
  for {
    ctx, span := trace.StartSpan(context.Background(), "main")
    span.AddAttributes(
      trace.StringAttribute("method", "POST"),
    )
    log.Printf("TraceId: %s\n", span.SpanContext().TraceID.String())
    resp, err := sendPostRequest(ctx,
      "http://localhost:8080/api/v1/ping")
    if err != nil {
      log.Printf("sendPostRequest: %v\n", err)
    }
    fmt.Printf("Response: %s\n", resp)
    span.End()

    time.Sleep(5 * time.Second)
  }
}

func sendPostRequest(ctx context.Context, url string) (string, error) {
  _ /* ctx2 */, span := trace.StartSpan(ctx, "sendPostRequest")
  defer span.End()

  spanContextJson, err := json.Marshal(span.SpanContext())
  if err != nil {
    return "", err
  }

  req, err := http.NewRequest("POST", url,  nil)
  if err != nil {
    return "", err
  }
  req.Header.Add("X-Span-Context", string(spanContextJson))

  client := http.Client{}
  resp, err := client.Do(req)
  if err != nil {
    return "", err
  }
  defer resp.Body.Close()

  bytes, err := ioutil.ReadAll(resp.Body)
  if err != nil {
    return "", err
  }

  return string(bytes), nil
}

Код сервера:

package main

import (
  "context"
  "encoding/json"
  "flag"
  "net/http"
  "go.opencensus.io/trace"
  "github.com/gorilla/mux"
  "github.com/sirupsen/logrus"
  "github.com/afiskon/golang-jaeger-example"
)

func PostHandler(w http.ResponseWriter, r *http.Request) {
  spanContextJson := r.Header.Get("X-Span-Context")
  var spanContext trace.SpanContext
  err := json.Unmarshal([]byte(spanContextJson), &spanContext)
  if err != nil {
    logrus.Errorf("PostHandler, json.Unmarshal: %v\n", err)
    return
  }

  _ /* ctx2 */, span := trace.StartSpanWithRemoteParent(
  context.Background(), "PostHandler", spanContext)
  defer span.End()

  logrus.Debugf("PostHandler called, traceId = %s\n",
  span.SpanContext().TraceID.String())

  h := w.Header()
  h.Set("Content-Type", "text/html")
  w.WriteHeader(200)
  _, err = w.Write([]byte("<h1>PONG</h1>\n"))
  if err != nil {
    logrus.Errorf("PostHandler, w.Write: %v\n", err)
  }
}

var listenAddr string

func main() {
  flag.StringVar(&listenAddr, "listen", ":8080",
    "Listen address")
  flag.Parse()

  logrus.SetLevel(logrus.DebugLevel)
  utils.InitJaeger("serer")

  logrus.Infof("Starting HTTP server at %s...",
    listenAddr)

  r := mux.NewRouter().
    PathPrefix("/api/v1").
    Path("/ping").
    Subrouter()

  r.Methods("POST").
    HandlerFunc(PostHandler)

  http.Handle("/", r)
  err := http.ListenAndServe(listenAddr, nil)
  if err != nil {
    logrus.Fatalf("http.ListenAndServe: %v\n", err)
  }

  logrus.Info("HTTP server terminated\n")
}

В принципе, все сводится к созданию span’ов и своевременному вызову span.End():

ctx2, span := trace.StartSpan(ctx1, "yetAnotherSpan")
defer span.End()

Тут главное не запутаться в Context’ах. Когда StartSpan возвращает вам новый контекст (ctx2), вложенные span’ы должны использовать этот контекст, а не родительский (ctx1). Иначе нарушится вложенность span’ов и в Jaeger мы увидим ерунду.

К span’у можно прикрепить дополнительную информацию:

ctx, span := trace.StartSpan(context.Background(), "main")
span.AddAttributes(
  trace.StringAttribute("method", "POST"),
)

Она также будет видна в Jaeger. TraceId можно как-то передать пользователю или записать в лог:

log.Printf("TraceId: %s\n", span.SpanContext().TraceID.String())

По TraceId в Jaeger можно найти полную трассировку запроса.

Наконец, чтобы обращения к разным сервисам объединялись в один трейс, используются SpanContext’ы:

// на клиенте:
spanContextJson, err := json.Marshal(span.SpanContext())

// на сервере:
err := json.Unmarshal(spanContextJson, &spanContext)
if err != nil {
  // ололо...
}

ctx2, span := trace.StartSpanWithRemoteParent(
  context.Background(), "PostHandler", spanContext)

В приведенном примере SpanContext сериализуется в JSON и передается через HTTP-заголовок. Само собой разумеется, передавать его можно любым другим способом.

Трейсы в Jaeger выглядят приблизительно так:

Пример трейса в Jaeger

Получается очень наглядно. Сразу видно, где и сколько времени проводил запрос, какие его куски и где выполнялись в параллель, и так далее. Воспринимать информацию в таком виде на порядок проще, чем грепать логи.

Полную версию исходников к посту вы найдете здесь. Как всегда, буду рад вашим вопросам и дополнениям.

Дополнение: Агрегация логов в распределенных системах с Go и Loki

Метки: , .

Понравился пост? Узнайте, как можно поддержать развитие этого блога.

Также подпишитесь на RSS, Facebook, ВКонтакте, Twitter или Telegram.