Contextual Logging: Keep Tracks Execution Flow
Tags: api, architecture, go, tutorial
Published: 2024-05-18 09:07:09

### Preamble
Have you ever been in a situation where you needed to trace the execution flow to find a bug, but had no idea what was happening, when a request started entering your business logic and flowed through various logic sets? At this moment, I want to share how to implement Contextual Logging to make it easier to trace the execution flow in business logic.

---

### Demonstration Project
I have coded a project to demonstrate how contextual logging flows across applications, or services. In this project, we have three services: Alpha, Bravo, and Charlie. Alpha sends requests to Bravo and Charlie when certain conditions are met. Afterward, I merge the log files from these services to see the correlated log lines, tracking the request as it enters the Alpha application and proceeds to the sub-applications, Bravo and Charlie. This allows us to trace the execution flows between these applications. Please clone this repository before we proceed to next section. [Contextual Logging Demonstration Git](https://github.com/xoxoist/cl-tutor).

---

### Business Logic Flow
The Business Logic Flow behind the project involves the execution of Alpha within the main function. Alpha requires two applications, Bravo and Charlie, which are used for string manipulation in a simple case. Once Alpha receives a request, it checks the content string for Bravo. If content is present, it sends a request to the Bravo app. Similarly, if there is content for Charlie, it sends a request to the Charlie app. The responses from Bravo and Charlie are then included in Alpha's response structure, which is returned using a print line. Throughout this process, logs are generated line by line to trace the execution flow. The sequence diagram provided offers a visual understanding of this flow.
![Flow](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/37cjlvrftwgv7lvkaz1p.png)

---

### Log Files
In this project, there are three log files, one for each application: Alpha, Bravo, and Charlie. These log files will be merged using Logstash, which I will discuss in the next episode. For now, we achieve this by merging them manually. Here is where the log file is located on the project.
![Log Files](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/tmcdtd4flrkbq6h93zn6.png)

---

### Logger Library Setup
You are free to choose any library for logging in your application, but for this implementation, I will use Zap Logger and Lumberjack for log file writer. [Zap Logger Git](https://github.com/uber-go/zap) and [Lumberjack Git](https://github.com/natefinch/lumberjack). We need to initialize a Zap Logger instance and use it across applications. Here is what the `logger/logger.go` file content looks like, and here is where the `logger.go` file is located.
![Logger](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/itgqmaad4hdbytdhona5.png)

#### Logger `logger/logger.go`
```go
package logger

import (
	"github.com/natefinch/lumberjack"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"os"
	"strings"
)

func NewZapLogger(logFileName, setMode, applicationVersion, applicationName string) *zap.SugaredLogger {
	// encode config mode checking and setup
	var encoderCfg zapcore.EncoderConfig
	if strings.Contains(setMode, "stg") ||
		strings.Contains(setMode, "prd") {
		encoderCfg = zap.NewProductionEncoderConfig()
	}
	encoderCfg.TimeKey = "timestamp"
	encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder

	// zap logging config setup using previous encoder config
	var config zap.Config
	config.Level = zap.NewAtomicLevelAt(zap.InfoLevel)
	config.Development = false
	config.DisableCaller = false
	config.DisableStacktrace = false
	config.Sampling = nil
	config.EncoderConfig = encoderCfg
	config.Encoding = "json"
	config.OutputPaths = []string{"stderr"}
	config.ErrorOutputPaths = []string{"stderr"}
	config.InitialFields = map[string]interface{}{
		"service_pid":     os.Getpid(),
		"service_name":    applicationName,
		"service_version": applicationVersion,
	}

	// Set up file output using Lumberjack
	fileSyncer := zapcore.AddSync(&lumberjack.Logger{
		Filename: logFileName,
	})

	// Create file core
	fileCore := zapcore.NewCore(zapcore.NewJSONEncoder(encoderCfg), fileSyncer, config.Level)
	core := zapcore.NewTee(
		zap.Must(config.Build()).Core(),
		fileCore.With([]zap.Field{
			zap.Int("service_pid", os.Getpid()),
			zap.String("service_name", applicationName),
			zap.String("service_version", applicationVersion),
		}),
	)

	// setup sugared log
	sugared := zap.New(core).Sugar()
	defer func(sugar *zap.SugaredLogger) {
		_ = sugar.Sync()
	}(sugared)
	return sugared
}
```

---

### Applications Code
In this demonstration, there are three applications inside the `applications` package, each wrapped in a package named `alpha`, `bravo`, and `charlie`. Inside these packages, there are Go files containing the business logic code. Here is the content of those files. And here is where the `applications` package looks like.
![Applications Package](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/prvpnzcj3nlomudnbwf4.png)


#### Alpha `alpha.go`
```go
package alpha

import (
	"context"
	"errors"
	"fmt"
	"github.com/xoxoist/cl-tutor/applications/bravo"
	"github.com/xoxoist/cl-tutor/applications/charlie"
	"go.uber.org/zap"
)

type (
	Request struct {
		AlphaContent   string
		BravoContent   string
		CharlieContent string
	}

	Response struct {
		BravoManipulatedContent   string
		CharlieManipulatedContent string
	}

	Alpha interface {
		AlphaLogicFlowEntry(ctx context.Context, req Request) (*Response, error)
		businessLogicFlow(ctx context.Context, req Request) (*Response, error)
		requestToBravoApp(ctx context.Context, req Request) (*bravo.Response, error)
		requestToCharlieApp(ctx context.Context, req Request) (*charlie.Response, error)
	}

	alpha struct {
		Name          string
		Version       string
		Package       string
		bravoClient   func(requestId string, request bravo.Request) (*bravo.Response, error)
		charlieClient func(requestId string, request charlie.Request) (*charlie.Response, error)
	}
)

func NewAlphaApplication(
	applicationName string,
	applicationVersion string,
	bravoClient func(requestId string, request bravo.Request) (*bravo.Response, error),
	charlieClient func(requestId string, request charlie.Request) (*charlie.Response, error),
) Alpha {
	return &alpha{
		Name:          applicationName,
		Version:       applicationVersion,
		Package:       "applications.alpha",
		bravoClient:   bravoClient,
		charlieClient: charlieClient,
	}
}

func (a *alpha) AlphaLogicFlowEntry(ctx context.Context, req Request) (*Response, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", a.Package, "AlphaLogicFlowEntry")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// executing business logic flow
	response, err := a.businessLogicFlow(ctx, req)
	if err != nil {
		cl.Errorw(fName, "reason", err.Error())
		return nil, errors.New("error while contacting charlie service")
	}

	// returning
	return response, nil
}

func (a *alpha) businessLogicFlow(ctx context.Context, req Request) (*Response, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", a.Package, "businessLogicFlow")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// var bravo and charlie manipulated string
	var bravoStr, charlieStr string

	// when string length inside req.BravoContent is 0
	// then calling bravo client
	if len(req.BravoContent) > 0 {
		br, err := a.requestToBravoApp(ctx, req)
		if err != nil {
			cl.Errorw(fName, "reason", err.Error())
			return nil, errors.New("error while contacting bravo service")
		}
		bravoStr = br.ManipulatedContent
	}

	// when string length inside req.CharlieContent is 0
	// then calling charlie client
	if len(req.CharlieContent) > 0 {
		cr, err := a.requestToCharlieApp(ctx, req)
		if err != nil {
			cl.Errorw(fName, "reason", err.Error())
			return nil, errors.New("error while contacting charlie service")
		}
		charlieStr = cr.ManipulatedContent
	}

	// returning
	return &Response{
		BravoManipulatedContent:   fmt.Sprintf("%s %s", req.AlphaContent, bravoStr),
		CharlieManipulatedContent: fmt.Sprintf("%s %s", req.AlphaContent, charlieStr),
	}, nil
}

func (a *alpha) requestToBravoApp(ctx context.Context, req Request) (*bravo.Response, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", a.Package, "requestToBravoApp")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// extract request id to be passed to bravo application
	requestId, ok := ctx.Value("Request-Id").(string)
	if !ok {
		return nil, errors.New("request id not pass through context")
	}

	// sending request to bravo application
	response, err := a.bravoClient(requestId, bravo.Request{
		Content: req.BravoContent,
	})
	if err != nil {
		cl.Errorw(fName, "reason", err.Error())
		return nil, errors.New("error while contacting bravo service")
	}

	// returning
	return response, nil
}

func (a *alpha) requestToCharlieApp(ctx context.Context, req Request) (*charlie.Response, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", a.Package, "requestToCharlieApp")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// extract request id to be passed to charlie application
	requestId, ok := ctx.Value("Request-Id").(string)
	if !ok {
		return nil, errors.New("request id not pass through context")
	}

	// sending request to charlie application
	response, err := a.charlieClient(requestId, charlie.Request{
		Content: req.CharlieContent,
	})
	if err != nil {
		cl.Errorw(fName, "reason", err.Error())
		return nil, errors.New("error while contacting charlie service")
	}

	// returning
	return response, nil
}
```

---

#### Bravo `bravo.go`
```go
package bravo

import (
	"context"
	"errors"
	"fmt"
	"go.uber.org/zap"
	"strings"
)

type (
	Request struct {
		Content string
	}

	Response struct {
		ManipulatedContent string
	}

	Bravo interface {
		BravoLogicFlowEntry(ctx context.Context, req Request) (*Response, error)
		reverseString(ctx context.Context, content string) (string, error)
	}

	bravo struct {
		Name    string
		Version string
		Package string
	}
)

func NewBravoApplication(
	applicationName string,
	applicationVersion string,
) Bravo {
	return &bravo{
		Name:    applicationName,
		Version: applicationVersion,
		Package: "applications.bravo",
	}
}

func (b *bravo) BravoLogicFlowEntry(ctx context.Context, req Request) (*Response, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", b.Package, "BravoLogicFlowEntry")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// reverse the string
	manipulated, err := b.reverseString(ctx, req.Content)
	if err != nil {
		cl.Errorw(fName, "reason", err.Error())
		return nil, errors.New("error while manipulate string")
	}

	// returning
	return &Response{
		ManipulatedContent: manipulated,
	}, nil
}

func (b *bravo) reverseString(ctx context.Context, content string) (string, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", b.Package, "reverseString")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return "", errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// manipulator
	runes := []rune(content)
	for i, j := 0, len(runes)-1; i < j; i, j = i+1, j-1 {
		runes[i], runes[j] = runes[j], runes[i]
	}
	manipulated := strings.ToUpper(string(runes))
	cl.Infow(fName, "manipulated_content", manipulated)

	// returning
	return manipulated, nil
}
```

---

#### Charlie `charlie.go`
```go
package charlie

import (
	"context"
	"errors"
	"fmt"
	"go.uber.org/zap"
	"strings"
)

type (
	Request struct {
		Content string
	}

	Response struct {
		ManipulatedContent string
	}

	Charlie interface {
		CharlieLogicFlowEntry(ctx context.Context, req Request) (*Response, error)
		replaceVowelsWithAsterisk(ctx context.Context, content string) (string, error)
	}

	charlie struct {
		Name    string
		Version string
		Package string
	}
)

func NewCharlieApplication(
	applicationName string,
	applicationVersion string,
) Charlie {
	return &charlie{
		Name:    applicationName,
		Version: applicationVersion,
		Package: "applications.charlie",
	}
}

func (c *charlie) CharlieLogicFlowEntry(ctx context.Context, req Request) (*Response, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", c.Package, "BravoLogicFlowEntry")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// reverse the string
	manipulated, err := c.replaceVowelsWithAsterisk(ctx, req.Content)
	if err != nil {
		cl.Errorw(fName, "reason", err.Error())
		return nil, errors.New("error while manipulate string")
	}

	// returning
	return &Response{
		ManipulatedContent: manipulated,
	}, nil
}

func (c *charlie) replaceVowelsWithAsterisk(ctx context.Context, content string) (string, error) {
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", c.Package, "replaceVowelsWithAsterisk")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return "", errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")

	// manipulator
	vowels := "AEIOUaeiou"
	var result strings.Builder
	for _, char := range content {
		if strings.ContainsRune(vowels, char) {
			result.WriteRune('*')
		} else {
			result.WriteRune(char)
		}
	}
	manipulated := result.String()
	cl.Infow(fName, "manipulated_content", manipulated)

	// returning
	return manipulated, nil
}
```

---

#### Main `main.go`
```go
package main

import (
	"context"
	"fmt"
	"github.com/xoxoist/cl-tutor/applications/alpha"
	"github.com/xoxoist/cl-tutor/applications/bravo"
	"github.com/xoxoist/cl-tutor/applications/charlie"
	"github.com/xoxoist/cl-tutor/logger"
	"go.uber.org/zap"
)

func ControllerAlphaApplication() (*alpha.Response, error) {
	// create logger
	const appName, logFile, logMode, version = "alpha", "logs/log.svc.a.log", "prd", "v1.0.0"
	lg := logger.NewZapLogger(logFile, logMode, version, appName)

	// prepare contextual logging
	const XRequestIDHeader = "1239893491327"
	requestData := alpha.Request{
		AlphaContent:   "John Doe",
		BravoContent:   "Hello World from Bravo to",
		CharlieContent: "Hello World from Charlie to",
	}
	lg = lg.With("request_id", XRequestIDHeader)
	lg = lg.With("request_data", requestData)

	// prepare context for contextual logging
	ctx := context.Background()
	ctx = context.WithValue(ctx, "Request-Id", XRequestIDHeader)
	ctx = context.WithValue(ctx, zap.SugaredLogger{}, lg)

	// calling business logic
	service := alpha.NewAlphaApplication(
		appName,
		version,
		ControllerBravoApplication,
		ControllerCharlieApplication,
	)
	response, err := service.AlphaLogicFlowEntry(ctx, requestData)
	if err != nil {
		return nil, err
	}
	return response, nil
}

func ControllerBravoApplication(requestId string, request bravo.Request) (*bravo.Response, error) {
	// create logger
	const appName, logFile, logMode, version = "bravo", "logs/log.svc.b.log", "prd", "v2.0.0"
	lg := logger.NewZapLogger(logFile, logMode, version, appName)

	// prepare contextual logging
	lg = lg.With("request_id", requestId)
	lg = lg.With("request_data", request)

	// prepare context for contextual logging
	ctx := context.Background()
	ctx = context.WithValue(ctx, "Request-Id", requestId)
	ctx = context.WithValue(ctx, zap.SugaredLogger{}, lg)

	// prepare context for contextual logging
	service := bravo.NewBravoApplication(appName, version)

	// calling business logic
	return service.BravoLogicFlowEntry(ctx, request)
}

func ControllerCharlieApplication(requestId string, request charlie.Request) (*charlie.Response, error) {
	// create logger
	const appName, logFile, logMode, version = "charlie", "logs/log.svc.c.log", "prd", "v3.0.0"
	lg := logger.NewZapLogger(logFile, logMode, version, appName)

	// prepare contextual logging
	lg = lg.With("request_id", requestId)
	lg = lg.With("request_data", request)

	// prepare context for contextual logging
	ctx := context.Background()
	ctx = context.WithValue(ctx, "Request-Id", requestId)
	ctx = context.WithValue(ctx, zap.SugaredLogger{}, lg)

	// prepare context for contextual logging
	service := charlie.NewCharlieApplication(appName, version)

	// calling business logic
	return service.CharlieLogicFlowEntry(ctx, request)
}

func main() {
	response, err := ControllerAlphaApplication()
	if err != nil {
		panic(err)
	}
	fmt.Println("BRAVO:", response.BravoManipulatedContent)
	fmt.Println("CHARLIE:", response.CharlieManipulatedContent)
}
```

---

#### Contextual Logging
Within each business logic function, there is a chunk of code responsible for combining the package name and function name. This combined information is stored inside the `fName` variable and is used for each line of logging. Additionally, the code extracts a `*zap.SugaredLogger` from the `ctx` where the log instance already contains `request_id` and `request_data` passed from the controller layer. Therefore, when the log instance is used, it already contains the necessary data for tracing. Here is the corresponding chunk of code.

```go
	// extract zap logger inside context that passed from controller where
	// request received and logger from controller its already has unique
	// request id everytime request received.
	fName := fmt.Sprintf("%s.%s", a.Package, "businessLogicFlow")
	cl, ok := ctx.Value(zap.SugaredLogger{}).(*zap.SugaredLogger)
	if !ok {
		return nil, errors.New("contextual logging not pass through context")
	}
	cl.Infow(fName, "reason", "execution started")
	defer cl.Infow(fName, "reason", "execution ended")
```

In certain cases, such as `requestToBravoApp` and `requestToCharlieApp` functions, there is a need to extract the `request_id` value. This extracted value will be passed to the next sub-application. in order to keep the next application still retains the same `request_id` while executing its business logic. Here is the corresponding code snippet.
```go
	// extract request id to be passed to charlie application
	requestId, ok := ctx.Value("Request-Id").(string)
	if !ok {
		return nil, errors.New("request id not pass through context")
	}

	// sending request to charlie application
	response, err := a.charlieClient(requestId, charlie.Request{
		Content: req.CharlieContent,
	})
	if err != nil {
		cl.Errorw(fName, "reason", err.Error())
		return nil, errors.New("error while contacting charlie service")
	}
```

So whenever you try to find logs which are contained certain `request_id` it will show you which are correlated line of logs. Each lines of log represents business logic execution flows, which are functions that executed while business logic function running. This is called Contextual Logging.

---

#### Merging Log Files and Test It
In this section we will try to retrieve certain lines of logs, by using this `1239893491327` request id. I have merge these log file `log.svc.a.log`, `log.svc.b.log` and `log.svc.c.log` into `log.txt` and now try to retrieve correlated lines by that request id using `awk` command. `awk` is tool for text processing similar with `grep`.

Command
```bash
awk '/"request_id":"1239893491327"/' log.txt
```
Response
```
{"level":"info","timestamp":"2024-05-17T18:41:21.312+0700","msg":"applications.alpha.AlphaLogicFlowEntry","service_pid":34716,"service_name":"alpha","service_version":"v1.0.0","request_id":"1239893491328","request_data":{"AlphaContent":"John Doe","BravoContent":"Hello World from Bravo to","CharlieContent":"Hello World from Charlie to"},"reason":"execution started"}
.......... other lines ..........
{"level":"info","timestamp":"2024-05-17T18:41:21.312+0700","msg":"applications.charlie.BravoLogicFlowEntry","service_pid":34716,"service_name":"charlie","service_version":"v3.0.0","request_id":"1239893491328","request_data":{"Content":"Hello World from Charlie to"},"reason":"execution ended"}
```
Even with simple command you can trace execution flow by the request id.

If you want use some formating that `awk` can does. Just perform your awk command.

Command
```bash
awk -F'[,:}]' '/"request_id":"1239893491327"/ {print "Function Name:", $8, "Timestamp:", $4, "Service Name:", $14, "Reason:", $22}' log.txt
```
Response
```
Function Name: "applications.alpha.AlphaLogicFlowEntry" Timestamp: "2024-05-17T18 Service Name: "v1.0.0" Reason: "CharlieContent"
.......... other lines ..........
Function Name: "applications.charlie.BravoLogicFlowEntry" Timestamp: "2024-05-17T18 Service Name: "v3.0.0" Reason: "execution ended"
```

To try different `request_id` you can change it in `main.go` file find this line code.
```go
const XRequestIDHeader = "1239893491327"
```
And change the random number, in real case this number generated by client who sent the request, or you can generate it automatically, but you need to return the request id everytime you application respond to client, this is like the key if a request gone wrong. So you can trace its flow using its request id.

This will be more interesting when the log file loaded using Logstash and feed to Kibana, as your log finder.

---

### Conclusion
Contextual Logging is crucial parts when you want to move into microservice architecture, where service might be communicate with other service. So when error happened in other service, you can still trace the execution flow across services. This might be helpful for improving maintainability, readability and help you to find error faster.

---

### My Thanks
Thank you for visiting! I hope you found it useful and enjoyable. Don't hesitate to reach out if you have any questions or feedback. Happy reading!