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.
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.
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.
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 and Lumberjack Git. 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 logger/logger.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.
Alpha alpha.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
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
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
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.
// 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.
// 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
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
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.
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!
Top comments (0)