Merge pull request #10 from abiddiscombe/9--Print-HTTP-and-database-l…

…ogs-to-console

#9 - Print HTTP and database logs to console

README.md

@@ -29,13 +29,18 @@ If the `alias` is vacant, a new unique record will be created for the provided `
 
 ## Deployment Instructions
 
-Concierge can be run as a Docker container and uses internal port `:3000`. \
-The latest release image of [abiddiscombe/concierge](https://hub.docker.com/repository/docker/abiddiscombe/concierge/general) can be pulled from Docker Hub.
+### Setup
 
-The API server is backed by PostgreSQL; the following environment variables are required:
+Concierge can be run as a Docker container and uses port `3000`. The latest release image of [abiddiscombe/concierge](https://hub.docker.com/repository/docker/abiddiscombe/concierge/general) can be pulled from Docker Hub.
 
-- `CONCIERGE_PG_HOST` - PostgreSQL Server URL
-- `CONCIERGE_PG_PORT` - PostgreSQL Server Port
-- `CONCIERGE_PG_NAME` - PostgreSQL Database Name
-- `CONCIERGE_PG_USER` - PostgreSQL Connection User
-- `CONCIERGE_PG_PASS` - PostgreSQL Connection Password
+Concierge uses PostgreSQL to persist data. The following environment variables are required to connect to a PostgreSQL server:
+
+- `CONCIERGE_PG_HOST` - DB URL
+- `CONCIERGE_PG_PORT` - DB Port
+- `CONCIERGE_PG_NAME` - DB Name
+- `CONCIERGE_PG_USER` - DB User
+- `CONCIERGE_PG_PASS` - DB Password
+
+### Logging
+
+Concierge uses the `log/slog` package to print structured logs. These can be captured and ingested by a supported third-party `syslog` service.

go.mod

@@ -3,6 +3,7 @@ module github.com/abiddiscombe/concierge
 go 1.22.1
 
 require (
+	github.com/alfonmga/slog-gorm v0.0.0-20230918104600-53fa2b611c42
 	github.com/labstack/echo/v4 v4.11.4
 	gorm.io/driver/postgres v1.5.7
 	gorm.io/gorm v1.25.9

go.sum

@@ -1,3 +1,5 @@
+github.com/alfonmga/slog-gorm v0.0.0-20230918104600-53fa2b611c42 h1:ydAr4vN7OYdmpWX7ca0dEGQf1Nl5lfZvIRTg63KJ+4Q=
+github.com/alfonmga/slog-gorm v0.0.0-20230918104600-53fa2b611c42/go.mod h1:2uDbFxQZPyIWIpz6C+nwmotBfkREmuVPRWEoH4cbs2s=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=

internal/controllers/link.go

@@ -26,25 +26,32 @@ func LinkGet(c echo.Context) error {
 	alias := c.Param("alias")
 
 	if alias == "" {
-		return c.JSON(http.StatusBadRequest, LinkResponse{
+		return echo.NewHTTPError(http.StatusBadRequest, LinkResponse{
 			Title:   "[Concierge] Alias Lookup",
-			Message: "Error. An 'alias' URL parameter must be provided.",
+			Message: "An 'alias' URL parameter must be provided.",
 		})
 	}
 
 	url, createdAt, err := database.LinkRead(alias)
 
-	if url == "" || err != nil {
-		errorMessage := fmt.Sprintf("Error. The provided 'alias' of '%s' does not exist.", alias)
-		return c.JSON(http.StatusNotFound, LinkResponse{
+	if err != nil {
+		return echo.NewHTTPError(http.StatusInternalServerError, LinkResponse{
+			Title:   "[Concierge] Alias Lookup",
+			Message: "Internal Server Error",
+		})
+	}
+
+	if url == "" {
+		errorMessage := fmt.Sprintf("The provided alias of '%s' does not exist.", alias)
+		return echo.NewHTTPError(http.StatusNotFound, LinkResponse{
 			Title:   "[Concierge] Alias Lookup",
 			Message: errorMessage,
 		})
 	}
 
 	return c.JSON(http.StatusOK, LinkResponse{
 		Title:   "[Concierge] Alias Lookup",
-		Message: "Success. Returned information for the alias entry.",
+		Message: "Returned information for the alias entry.",
 		Metadata: &LinkResponseMetadata{
 			URL:       fmt.Sprintf("https://%s", url),
 			Link:      fmt.Sprintf("https://%s/to/%s", c.Request().Host, alias),
@@ -59,9 +66,9 @@ func LinkPost(c echo.Context) error {
 	alias := c.Param("alias")
 
 	if url == "" || alias == "" {
-		return c.JSON(http.StatusBadRequest, LinkResponse{
+		return echo.NewHTTPError(http.StatusBadRequest, LinkResponse{
 			Title:   "[Concierge] Alias Creation",
-			Message: "Error. Both 'url' and 'alias' parameters must be provided.",
+			Message: "Both 'url' and 'alias' parameters must be provided.",
 		})
 	}
 
@@ -70,32 +77,41 @@ func LinkPost(c echo.Context) error {
 	for _, value := range PROTOCOLS {
 		index := strings.Contains(url, value)
 		if index {
-			return c.JSON(http.StatusBadRequest, LinkResponse{
+			return echo.NewHTTPError(http.StatusBadRequest, LinkResponse{
 				Title:   "[Concierge] Alias Creation",
-				Message: "Error. The 'url' must not include a protocol (e.g. 'https://').",
+				Message: "The 'url' must not include a protocol (e.g. 'https://').",
 			})
 		}
 	}
 
 	if url[0:1] == "/" {
-		return c.JSON(http.StatusBadRequest, LinkResponse{
+		return echo.NewHTTPError(http.StatusBadRequest, LinkResponse{
 			Title:   "[Concierge] Alias Creation",
-			Message: "Error. The 'url' must start with a fully-qualified domain name.",
+			Message: "The 'url' must start with a fully-qualified domain name.",
 		})
 	}
 
-	_, createdAt, err := database.LinkWrite(url, alias)
+	url, createdAt, err := database.LinkWrite(url, alias)
 
 	if err != nil {
-		return c.JSON(http.StatusBadRequest, LinkResponse{
+		// This approach of determining if an HTTP-500 error
+		// has occurred is rather hacky. To be revisted later.
+		errorStartingText := err.Error()[0:26]
+		if errorStartingText == "ERROR: duplicate key value" {
+			return echo.NewHTTPError(http.StatusBadRequest, LinkResponse{
+				Title:   "[Concierge] Alias Creation",
+				Message: "The specified alias already exists.",
+			})
+		}
+		return echo.NewHTTPError(http.StatusInternalServerError, LinkResponse{
 			Title:   "[Concierge] Alias Creation",
-			Message: "Error. The specified 'alias' already exists.",
+			Message: "Internal Server Error",
 		})
 	}
 
 	return c.JSON(http.StatusCreated, LinkResponse{
 		Title:   "[Concierge] Alias Creation",
-		Message: "Success. A new alias entry has been created.",
+		Message: "A new alias entry has been created.",
 		Metadata: &LinkResponseMetadata{
 			URL:       fmt.Sprintf("https://%s", url),
 			Link:      fmt.Sprintf("https://%s/to/%s", c.Request().Host, alias),

internal/controllers/root.go

@@ -26,16 +26,16 @@ func RootGet(c echo.Context) error {
 				Title:   "Root (Self)",
 				Summary: "[GET] Returns information about this API.",
 			},
-			{
-				Href:    "/link",
-				Title:   "Link & Alias Management",
-				Summary: "[GET, POST] Lookup or create new aliases.",
-			},
 			{
 				Href:    "/to/:alias",
-				Title:   "Link Activation & Redirection",
+				Title:   "Link Redirection",
 				Summary: "[GET] Accepts a valid alias and redirects to target URL",
 			},
+			{
+				Href:    "/link/:alias",
+				Title:   "Link & Alias Management",
+				Summary: "[GET, POST] Lookup existing or create new aliases.",
+			},
 		},
 	})
 }

internal/controllers/to.go

@@ -17,18 +17,25 @@ func ToGet(c echo.Context) error {
 	alias := c.Param("alias")
 
 	if alias == "" {
-		return c.JSON(http.StatusNotFound, ToGetResponse{
-			Title:   "[Concierge] Alias Missing.",
+		return echo.NewHTTPError(http.StatusNotFound, ToGetResponse{
+			Title:   "[Concierge] Alias Redirection.",
 			Message: "An '/alias' value must be provided.",
 		})
 	}
 
 	url, _, err := database.LinkRead(alias)
 
-	if url == "" || err != nil {
-		return c.JSON(http.StatusNotFound, ToGetResponse{
-			Title:   "[Concierge] Alias Invalid.",
-			Message: "The '/alias' provided is not valid.",
+	if err != nil {
+		return echo.NewHTTPError(http.StatusInternalServerError, ToGetResponse{
+			Title:   "[Concierge] Alias Redirection.",
+			Message: "Internal Server Error",
+		})
+	}
+
+	if url == "" {
+		return echo.NewHTTPError(http.StatusNotFound, ToGetResponse{
+			Title:   "[Concierge] Alias Redirection.",
+			Message: "The provided 'alias' is not valid.",
 		})
 	}
 

internal/database/database.go

@@ -4,6 +4,8 @@ import (
 	"fmt"
 	"os"
 
+	"github.com/abiddiscombe/concierge/internal/log"
+	slogGorm "github.com/alfonmga/slog-gorm"
 	"gorm.io/driver/postgres"
 	"gorm.io/gorm"
 )
@@ -28,23 +30,37 @@ func parseEnv(key string) string {
 }
 
 func Init() {
-
 	dbHost := parseEnv("CONCIERGE_PG_HOST")
 	dbUser := parseEnv("CONCIERGE_PG_USER")
 	dbPass := parseEnv("CONCIERGE_PG_PASS")
 	dbName := parseEnv("CONCIERGE_PG_NAME")
 	dbPort := parseEnv("CONCIERGE_PG_PORT")
 
+	logger := log.NewLogger("database")
+
+	DBLogger := slogGorm.New(
+		slogGorm.WithLogger(logger),
+	)
+
 	connString := fmt.Sprintf("host=%s user=%s password=%s dbname=%s port=%s sslmode=prefer TimeZone=Europe/London", dbHost, dbUser, dbPass, dbName, dbPort)
-	db, err := gorm.Open(postgres.Open(connString), &gorm.Config{})
+	db, err := gorm.Open(postgres.Open(connString), &gorm.Config{
+		Logger: DBLogger,
+	})
 
 	if err != nil {
-		panic("Failed to connect to PostgreSQL (via GORM).")
+		msg := "Failed to connect to PostgreSQL"
+		logger.Error(msg)
+		panic(msg)
 	}
 
-	db.AutoMigrate(&UriLinkEntry{})
+	err = db.AutoMigrate(&UriLinkEntry{})
 
-	fmt.Println("[Concierge] Connected to PostgreSQL.")
+	if err != nil {
+		msg := "Failed to sync models with PostgreSQL"
+		logger.Error(msg)
+		panic(msg)
+	}
 
+	logger.Info("Connected to PostgreSQL")
 	DB = db
 }

internal/database/link.go

@@ -1,6 +1,7 @@
 package database
 
 import (
+	"errors"
 	"time"
 )
 
@@ -12,10 +13,10 @@ func parseTimestamp(unixTimestamp int64) string {
 func LinkRead(alias string) (string, string, error) {
 
 	var result UriLinkEntry
-	err := DB.Find(&result, UriLinkEntry{Alias: alias})
+	dbResponse := DB.Find(&result, UriLinkEntry{Alias: alias})
 
-	if err == nil {
-		return "", "", DB.Error
+	if dbResponse.Error != nil {
+		return "", "", errors.New(dbResponse.Error.Error())
 	}
 
 	createdAtStr := parseTimestamp(result.CreatedAt)
@@ -29,10 +30,10 @@ func LinkWrite(url string, alias string) (string, string, error) {
 		CreatedAt: 0,
 	}
 
-	result := DB.Create(&link)
+	dbResponse := DB.Create(&link)
 
-	if result.Error != nil {
-		return "", "", result.Error
+	if dbResponse.Error != nil {
+		return "", "", errors.New(dbResponse.Error.Error())
 	}
 
 	createdAtStr := parseTimestamp(link.CreatedAt)

internal/log/log.go

@@ -0,0 +1,14 @@
+package log
+
+import (
+	"log/slog"
+	"os"
+	"strings"
+)
+
+var logHandler = slog.NewTextHandler(os.Stdout, nil)
+
+func NewLogger(service string) *slog.Logger {
+	baseLogger := slog.New(logHandler)
+	return baseLogger.With("zone", strings.ToUpper(service))
+}

internal/server/server.go

@@ -1,17 +1,50 @@
 package server
 
 import (
-	"fmt"
+	"context"
+	"log/slog"
+	"net/http"
 
 	"github.com/abiddiscombe/concierge/internal/controllers"
+	"github.com/abiddiscombe/concierge/internal/log"
 	"github.com/labstack/echo/v4"
 	"github.com/labstack/echo/v4/middleware"
 )
 
 func Init() {
+	logger := log.NewLogger("server")
+
 	server := echo.New()
+	server.HidePort = true
 	server.HideBanner = true
+
 	server.Pre(middleware.RemoveTrailingSlash())
+	server.Use(middleware.Recover())
+	server.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
+		LogStatus:   true,
+		LogMethod:   true,
+		LogURI:      true,
+		LogError:    true,
+		HandleError: true,
+		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
+			var logLevel slog.Level
+			if v.Error == nil {
+				logLevel = slog.LevelInfo
+			} else if v.Status >= 400 && v.Status <= 499 {
+				logLevel = slog.LevelWarn
+			} else {
+				logLevel = slog.LevelError
+			}
+
+			logger.LogAttrs(context.Background(), logLevel, "HTTP Event",
+				slog.Int("status", v.Status),
+				slog.String("method", v.Method),
+				slog.String("uri", v.URI),
+			)
+
+			return nil
+		},
+	}))
 
 	server.GET("/", controllers.RootGet)
 
@@ -23,6 +56,7 @@ func Init() {
 	server.GET("/link/:alias", controllers.LinkGet)
 	server.POST("/link/:alias", controllers.LinkPost)
 
-	fmt.Println("[Concierge] Server Starting.")
-	server.Start(":3000")
+	if err := server.Start(":3000"); err != http.ErrServerClosed {
+		logger.Error("Server closed unexpectedly", "err", err)
+	}
 }