Trace RPC with logs

How to trace RPC with logs?

Overview

Sometimes, we don’t want to install any of tracing service like jaeger because of cost. In that case, we need a way to trace RPC with logs only.

Bootstrapper introduce a way to trace RPC with openTelemetry library but without tracing service.

Concept

RK bootstrapper will use traceId to track each RPC in distributed system which will be logged into RPC log while tracing and log interceptor enabled in bootstrapper.

EventId

EventId would be generated if logging interceptor/middleware was enabled bellow:

---
echo:
  - name: greeter
    port: 8080
    enabled: true
    interceptors:
      loggingZap:
        enabled: true
------------------------------------------------------------------------
...
ids={"eventId":"cd617f0c-2d93-45e1-bef0-95c89972530d"}
...

RequestId

Generated by meta interceptor/middleware automatically if user enabled bellow:

---
echo:
  - name: greeter
    port: 8080
    enabled: true
    interceptors:
      meta:
        enabled: true
      loggingZap:
        enabled: true
------------------------------------------------------------------------
...
ids={"eventId":"8226ba9b-424e-4e19-ba63-d37ca69028b3","requestId":"8226ba9b-424e-4e19-ba63-d37ca69028b3"}
...

If meta interceptor/middleware was enabled or requestId was enabled by user, then eventId will be override by requestId.

Simply, eventId will always the same as requestId

  rkechoctx.SetHeaderToClient(ctx, rkechoctx.RequestIdKey, "overridden-request-id")
------------------------------------------------------------------------
...
ids={"eventId":"overridden-request-id","requestId":"overridden-request-id"}
...

TraceId

Generated if user enable tracing interceptor/middleware by user as bellow:

---
echo:
  - name: greeter
    port: 8080
    enabled: true
    interceptors:
      meta:
        enabled: true
      loggingZap:
        enabled: true
      tracingTelemetry:
        enabled: true
------------------------------------------------------------------------
...
ids={"eventId":"dd19cf9a-c7be-486c-b29d-7af777a78ebe","requestId":"dd19cf9a-c7be-486c-b29d-7af777a78ebe","traceId":"316a7b475ff500a76bfcd6147036951c"}
...

Quick start

1.Create ServerA at 8080

bootA.yaml

---
echo:
  - name: greeter
    port: 8080
    enabled: true
    interceptors:
      meta:
        enabled: true
      loggingZap:
        enabled: true
      tracingTelemetry:
        enabled: true

serverA.go

package main

import (
	"context"
	"github.com/labstack/echo/v4"
	"github.com/rookie-ninja/rk-boot"
	"github.com/rookie-ninja/rk-echo/interceptor/context"
	"net/http"
)

// Application entrance.
func main() {
	// Create a new boot instance.
	boot := rkboot.NewBoot(rkboot.WithBootConfigPath("bootA.yaml"))

	// Register handler
	boot.GetEchoEntry("greeter").Echo.GET("/v1/hello", func(ctx echo.Context) error {
		client := http.DefaultClient

        // Construct request point to Server B
		req, _ := http.NewRequestWithContext(context.Background(), http.MethodGet, "http://localhost:8081/v1/hello", nil)

		// Inject parent trace info into request header
		rkechoctx.InjectSpanToHttpRequest(ctx, req)

        // Send request to Server B
		client.Do(req)

		return ctx.JSON(http.StatusOK, "Hello!")
	})

	// Bootstrap
	boot.Bootstrap(context.Background())

	// Wait for shutdown sig
	boot.WaitForShutdownSig(context.Background())
}

2.Create ServerB at 8081

bootB.yaml

---
echo:
  - name: greeter
    port: 8081
    enabled: true
    interceptors:
      meta:
        enabled: true
      loggingZap:
        enabled: true
      tracingTelemetry:
        enabled: true

serverB.go

package main

import (
	"context"
	"github.com/labstack/echo/v4"
	"github.com/rookie-ninja/rk-boot"
	"net/http"
)

// Application entrance.
func main() {
	// Create a new boot instance.
	boot := rkboot.NewBoot(rkboot.WithBootConfigPath("bootB.yaml"))

	// Register handler
	boot.GetEchoEntry("greeter").Echo.GET("/v1/hello", func(ctx echo.Context) error {
		return ctx.JSON(http.StatusOK, "Hello!")
	})

	// Bootstrap
	boot.Bootstrap(context.Background())

	// Wait for shutdown sig
	boot.WaitForShutdownSig(context.Background())
}

3.Start ServerA and ServerB

$ go run serverA.go
$ go run serverB.go

4.Send request to ServerA

$ curl localhost:8080/v1/hello

5.Validate logs

Two server will have same traceId in event log but different requestId and eventId.

What we need to do is grep same traceId.

ServerA

------------------------------------------------------------------------
...
ids={"eventId":"9b2e9278-0e19-4936-9afe-966ff7fce1c9","requestId":"9b2e9278-0e19-4936-9afe-966ff7fce1c9","traceId":"fc3801be6de88116a7c47fafca6a7328"}
...

ServerB

------------------------------------------------------------------------
...
ids={"eventId":"7b9585de-eaa3-4ad5-ae7a-e3be7fdb312e","requestId":"7b9585de-eaa3-4ad5-ae7a-e3be7fdb312e","traceId":"fc3801be6de88116a7c47fafca6a7328"}
...
Last modified November 2, 2021 : Add Echo framework documentation (80ec258)