Web-APP: Add gracefully shutdown, JSON structured logging

cmd/aznum2words-webapp/aznum2words-webapp.go

@@ -1,15 +1,24 @@
 package main
 
 import (
+	"context"
+	"fmt"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/api/converterapi"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/api/healthapi"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/config"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/handler"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/logger"
 	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/router"
+	"net/http"
+	"os"
+	"os/signal"
+	"syscall"
+	"time"
 )
 
 func main() {
-	config.LoadConfig()
+	logger := logger.Logger()
+	defer logger.Sync()
 
 	// Create an instance of our handler which satisfies the generated interface
 	var converterApi = new(converterapi.Api)
@@ -24,13 +33,45 @@ func main() {
 	routerPrometheus := router.NewPrometheusServer(routerApp)
 
 	go func() {
-		routerPrometheus.Logger.Fatal(routerPrometheus.Start(
-			config.GetConfig().GetMetricNetListenAddr()),
-		)
+		logger.
+			Info(fmt.Sprintf("prometheus server started at %s", config.GetConfig().GetAppNetListenAddr()))
+
+		if err := routerPrometheus.Start(config.GetConfig().GetMetricNetListenAddr()); err != nil && err != http.ErrServerClosed {
+			routerPrometheus.Logger.Fatal("shutting down the prometheus server")
+		}
+	}()
+
+	go func() {
+		logger.
+			Info(fmt.Sprintf("app server started at %s", config.GetConfig().GetAppNetListenAddr()))
+
+		if err := routerApp.Start(config.GetConfig().GetAppNetListenAddr()); err != nil && err != http.ErrServerClosed {
+			routerApp.Logger.Fatal("shutting down the app server")
+		}
 	}()
 
-	// And we serve HTTP until the world ends.
-	routerApp.Logger.Fatal(routerApp.Start(
-		config.GetConfig().GetAppNetListenAddr(),
-	))
+	// Wait for interrupt signal to gracefully shut down the server with a timeout of 10 seconds.
+	// Use a buffered channel to avoid missing signals as recommended for signal.Notify
+	quit := make(chan os.Signal, 1)
+	signal.Notify(quit, os.Interrupt, syscall.SIGTERM, syscall.SIGKILL)
+	<-quit
+
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+	defer cancel()
+
+	if err := routerApp.Shutdown(ctx); err != nil {
+		logger.
+			Error(fmt.Sprintf("an error occurred when shutdown app server, err: %s", err))
+	} else {
+		logger.
+			Info("gracefully shut downed app server")
+	}
+
+	if err := routerPrometheus.Shutdown(ctx); err != nil {
+		logger.
+			Error(fmt.Sprintf("an error occurred when shutdown prometheus server, err: %s", err))
+	} else {
+		logger.
+			Info("gracefully shut downed prometheus server")
+	}
 }

cmd/aznum2words-webapp/config/config.go

@@ -11,9 +11,11 @@ import (
 
 // Config holds a configuration variables.
 type Config struct {
+	AppName    string `arg:"-n, env:APP_NAME" default:"aznum2words-webapp"`
 	AppHost    string `arg:"-h, env:APP_HOST" default:"0.0.0.0"`
 	AppPort    string `arg:"-p, env:APP_PORT" default:"8080"`
 	MetricPort string `arg:"-m, env:METRIC_PORT" default:"9090"`
+	DeployEnv  string `arg:"-d, env:DEPLOY_ENV" default:"local"`
 }
 
 func (this *Config) GetAppNetListenAddr() string {
@@ -35,9 +37,9 @@ func (this *Config) GetMetricNetListenAddr() string {
 var conf *Config = &Config{}
 
 // LoadConfig ...
-func LoadConfig() {
+func init() {
 	// Local development purpose
-	if env := os.Getenv(constant.DEPLOY_ENV_KEY); env == "" {
+	if env := os.Getenv(constant.DEPLOY_ENV_KEY); env == constant.LOCAL_ENVIRONMENT {
 		errLoad := godotenv.Load(".env.local")
 
 		if errLoad != nil {

cmd/aznum2words-webapp/constant/config.go

@@ -3,3 +3,7 @@ package constant
 const (
 	DEPLOY_ENV_KEY = "DEPLOY_ENV"
 )
+
+const (
+	LOCAL_ENVIRONMENT = "local"
+)

cmd/aznum2words-webapp/logger/logging.go

@@ -0,0 +1,47 @@
+package logger
+
+import (
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/config"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/constant"
+	"log"
+	"time"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+var logger *zap.Logger
+
+func init() {
+	encoderConfig := zap.NewProductionConfig()
+	encoderConfig.Level.SetLevel(zapcore.InfoLevel)
+	if config.GetConfig().DeployEnv == constant.LOCAL_ENVIRONMENT {
+		encoderConfig.Level.SetLevel(zapcore.DebugLevel)
+	}
+	encoderConfig.EncoderConfig.TimeKey = "timestamp"
+	encoderConfig.EncoderConfig.MessageKey = "message"
+	encoderConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.RFC3339Nano)
+
+	zapLogger, err := encoderConfig.Build()
+	if err != nil {
+		log.Fatalf("fail to build log. err: %s", err)
+	}
+
+	for k, v := range GetDefaultLogEntries() {
+		zapLogger = zapLogger.
+			With(zap.Any(k, v))
+	}
+
+	logger = zapLogger
+}
+
+func Logger() *zap.Logger {
+	return logger
+}
+
+func GetDefaultLogEntries() map[string]string {
+	return map[string]string{
+		"app": config.GetConfig().AppName,
+		"env": config.GetConfig().DeployEnv,
+	}
+}

cmd/aznum2words-webapp/router/router.go

@@ -1,29 +1,26 @@
 package router
 
 import (
+	"fmt"
+	"github.com/egasimov/aznum2words/cmd/aznum2words-webapp/logger"
 	"github.com/labstack/echo-contrib/prometheus"
 	"github.com/labstack/echo/v4"
 	echomiddleware "github.com/labstack/echo/v4/middleware"
+	"strings"
 )
 
-var loggerConfig = echomiddleware.LoggerConfig{
-	Format: `{"time":"${time_rfc3339_nano}","x-correlation-id":"${header:x-correlation-id}","remote_ip":"${remote_ip}",` +
-		`"host":"${host}","method":"${method}","uri":"${uri}","user_agent":"${user_agent}",` +
-		`"status":${status},"error":"${error}","latency":${latency},"latency_human":"${latency_human}"}` + "\n",
-	CustomTimeFormat: "2006-01-02 15:04:05.00000",
-}
-
 func NewMainServer() *echo.Echo {
 	echoMainServer := echo.New()
 	echoMainServer.HideBanner = true
+	echoMainServer.HidePort = true
 
 	echoMainServer.Use(echomiddleware.CORS())
 	echoMainServer.Use(echomiddleware.RequestIDWithConfig(
 		echomiddleware.RequestIDConfig{
 			TargetHeader: echo.HeaderXCorrelationID,
 		}))
 	// Log all requests
-	echoMainServer.Use(echomiddleware.LoggerWithConfig(loggerConfig))
+	echoMainServer.Use(echomiddleware.LoggerWithConfig(getLoggerConfig()))
 
 	return echoMainServer
 }
@@ -32,14 +29,14 @@ func NewPrometheusServer(echoMainServer *echo.Echo) *echo.Echo {
 	// Create Prometheus server and Middleware
 	echoPrometheus := echo.New()
 	echoPrometheus.HideBanner = true
-
+	echoPrometheus.HidePort = true
 	echoPrometheus.Use(echomiddleware.CORS())
 	echoPrometheus.Use(echomiddleware.RequestIDWithConfig(
 		echomiddleware.RequestIDConfig{
 			TargetHeader: echo.HeaderXCorrelationID,
 		}))
 	// Log all requests
-	echoPrometheus.Use(echomiddleware.LoggerWithConfig(loggerConfig))
+	echoPrometheus.Use(echomiddleware.LoggerWithConfig(getLoggerConfig()))
 
 	prom := prometheus.NewPrometheus("echo", nil)
 
@@ -51,3 +48,32 @@ func NewPrometheusServer(echoMainServer *echo.Echo) *echo.Echo {
 
 	return echoPrometheus
 }
+
+func getLoggerConfig() echomiddleware.LoggerConfig {
+	return echomiddleware.LoggerConfig{
+		Format: `{"time":"${time_rfc3339_nano}","x-correlation-id":"${header:x-correlation-id}","remote_ip":"${remote_ip}",` +
+			`"host":"${host}","method":"${method}","uri":"${uri}","user_agent":"${user_agent}",` +
+			addDefaultLogEntries() +
+			`"status":${status},"error":"${error}","latency":${latency},"latency_human":"${latency_human}"}` + "\n",
+		CustomTimeFormat: "2006-01-02 15:04:05.00000",
+	}
+}
+
+func addDefaultLogEntries() string {
+	var logEntries []string
+	for k, v := range logger.GetDefaultLogEntries() {
+		logEntries = append(logEntries, addKeyValPair(k, v, true))
+	}
+
+	return strings.Join(logEntries, "")
+}
+
+func addKeyValPair(keyName string, valName string, appendComma bool) string {
+	var result string
+	if appendComma {
+		result = fmt.Sprintf(`"%s":"%s",`, keyName, valName)
+	} else {
+		result = fmt.Sprintf(`"%s":"%s"`, keyName, valName)
+	}
+	return result
+}