Skip to content

Commit

Permalink
implement structured logging with zerolog
Browse files Browse the repository at this point in the history
Merge branch 'zerolog'

logs will be pretty-printed to the console by development builds
compiled with main.releaseMode=false and printed to stderr as JSON
in release builds where main.releaseMode=true
  • Loading branch information
jantari committed May 15, 2023
2 parents e254d03 + f2852e7 commit 2a5cb16
Show file tree
Hide file tree
Showing 7 changed files with 166 additions and 55 deletions.
27 changes: 12 additions & 15 deletions controllers/packages.go
Original file line number Diff line number Diff line change
@@ -1,11 +1,9 @@
package controllers

import (
"fmt"
"log"

"github.com/gin-gonic/gin"

"rewinged/logging"
"rewinged/models"
)

Expand All @@ -14,13 +12,12 @@ func GetPackages(c *gin.Context) {
Data: models.Manifests.GetAllPackageIdentifiers(),
}

fmt.Println(response)
logging.Logger.Debug().Msgf("%v", response)
c.JSON(200, response)
}

func GetPackage(c *gin.Context) {
fmt.Println("/packageManifests: Someone tried to GET package '", c.Param("package_identifier"), "'")
fmt.Println("with query params:", c.Request.URL.Query())
logging.Logger.Debug().Msgf("/packageManifests: Someone tried to GET package '%v' with query params: %v", c.Param("package_identifier"), c.Request.URL.Query())

response := models.API_ManifestSingleResponse_1_1_0 {
RequiredQueryParameters: []string{},
Expand All @@ -30,7 +27,7 @@ func GetPackage(c *gin.Context) {

var pkg []models.API_ManifestVersionInterface = models.Manifests.GetAllVersions(c.Param("package_identifier"))
if len(pkg) > 0 {
fmt.Println("the package was found!")
logging.Logger.Debug().Msgf("the package was found")

response.Data = &models.API_Manifest_1_1_0{
PackageIdentifier: c.Param("package_identifier"),
Expand All @@ -39,7 +36,7 @@ func GetPackage(c *gin.Context) {

c.JSON(200, response)
} else {
fmt.Println("the package was NOT found!")
logging.Logger.Debug().Msgf("the package was not found")
c.JSON(404, models.API_WingetApiError{
ErrorCode: 404,
ErrorMessage: "The specified package was not found.",
Expand All @@ -50,7 +47,7 @@ func GetPackage(c *gin.Context) {
func SearchForPackage(c *gin.Context) {
var post models.API_ManifestSearchRequest_1_1_0
if err := c.BindJSON(&post); err == nil {
fmt.Printf("%+v\n", post)
logging.Logger.Debug().Msgf("%+v", post)
response := &models.API_ManifestSearchResult[models.API_ManifestSearchVersion_1_1_0]{
RequiredPackageMatchFields: []string{},
Data: []models.API_ManifestSearchResponse[models.API_ManifestSearchVersion_1_1_0] {},
Expand All @@ -62,18 +59,18 @@ func SearchForPackage(c *gin.Context) {
var results map[string][]models.API_ManifestVersionInterface

if post.Query.KeyWord != "" {
fmt.Println("someone searched the repo for:", post.Query.KeyWord)
logging.Logger.Debug().Msgf("someone searched the repo for: %v", post.Query.KeyWord)
results = models.Manifests.GetByKeyword(post.Query.KeyWord)
} else if (post.Inclusions != nil && len(post.Inclusions) > 0) || (post.Filters != nil && len(post.Filters) > 0) {
fmt.Println("advanced search with inclusions[] and/or filters[]")
logging.Logger.Debug().Msg("advanced search with inclusions[] and/or filters[]")
results = models.Manifests.GetByMatchFilter(post.Inclusions, post.Filters)
}

fmt.Println("... with", len(results), "results:")
logging.Logger.Debug().Msgf("with %v results", len(results))

if len(results) > 0 {
for packageId, packageVersions := range results {
fmt.Println(" package", packageId, "with", len(packageVersions), "versions.")
logging.Logger.Debug().Msgf("package %v with %v versions", packageId, len(packageVersions))
var versions []models.API_ManifestSearchVersion_1_1_0

for _, version := range packageVersions {
Expand All @@ -92,14 +89,14 @@ func SearchForPackage(c *gin.Context) {
Versions: versions,
})
}
fmt.Printf("%+v\n", response)
logging.Logger.Debug().Msgf("%+v", response)
c.JSON(200, response)
} else {
// winget REST-API specification calls for a 204 return code if no results were found
c.JSON(204, response)
}
} else {
log.Println("error deserializing json post body %v\n", err)
logging.Logger.Error().Err(err).Msg("error deserializing json post body")
}
}

6 changes: 4 additions & 2 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ require (
github.com/gin-gonic/gin v1.7.7
github.com/peterbourgon/ff/v3 v3.3.0
github.com/rjeczalik/notify v0.9.2
github.com/rs/zerolog v1.29.0
gopkg.in/yaml.v3 v3.0.1
)

Expand All @@ -17,11 +18,12 @@ require (
github.com/golang/protobuf v1.3.3 // indirect
github.com/json-iterator/go v1.1.9 // indirect
github.com/leodido/go-urn v1.2.0 // indirect
github.com/mattn/go-isatty v0.0.12 // indirect
github.com/mattn/go-colorable v0.1.13 // indirect
github.com/mattn/go-isatty v0.0.18 // indirect
github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421 // indirect
github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 // indirect
github.com/ugorji/go/codec v1.1.7 // indirect
golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9 // indirect
golang.org/x/sys v0.0.0-20220915200043-7b5979e65e41 // indirect
golang.org/x/sys v0.7.0 // indirect
gopkg.in/yaml.v2 v2.4.0 // indirect
)
22 changes: 19 additions & 3 deletions go.sum
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
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=
Expand All @@ -13,25 +14,36 @@ github.com/go-playground/universal-translator v0.17.0 h1:icxd5fm+REJzpZx7ZfpaD87
github.com/go-playground/universal-translator v0.17.0/go.mod h1:UkSxE5sNxxRwHyU+Scu5vgOQjsIJAF8j9muTVoKLVtA=
github.com/go-playground/validator/v10 v10.4.1 h1:pH2c5ADXtd66mxoE0Zm9SUhxE20r7aM3F26W0hOn+GE=
github.com/go-playground/validator/v10 v10.4.1/go.mod h1:nlOn6nFhuKACm19sB/8EGNn9GlaMV7XkbRSipzJ0Ii4=
github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
github.com/golang/protobuf v1.3.3 h1:gyjaxf+svBWX08ZjK86iN9geUJF0H6gp2IRKX6Nf6/I=
github.com/golang/protobuf v1.3.3/go.mod h1:vzj43D7+SQXF/4pzW/hwtAqwc6iTitCiVSaWz5lYuqw=
github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
github.com/json-iterator/go v1.1.9 h1:9yzud/Ht36ygwatGx56VwCZtlI/2AD15T1X2sjSuGns=
github.com/json-iterator/go v1.1.9/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
github.com/leodido/go-urn v1.2.0 h1:hpXL4XnriNwQ/ABnpepYM/1vCLWNDfUNts8dX3xTG6Y=
github.com/leodido/go-urn v1.2.0/go.mod h1:+8+nEpDfqqsY+g338gtMEUOtuK+4dEMhiQEgxpxOKII=
github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY=
github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
github.com/mattn/go-isatty v0.0.18 h1:DOKFKCQ7FNG2L1rbrmstDN4QVRdS89Nkh85u68Uwp98=
github.com/mattn/go-isatty v0.0.18/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421 h1:ZqeYNhU3OHLH3mGKHDcjJRFFRrJa6eAM5H+CtDdOsPc=
github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q=
github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 h1:Esafd1046DLDQ0W1YjYsBW+p8U2u7vzgW2SQVmlNazg=
github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742/go.mod h1:bx2lNnkwVCuqBIxFjflWJWanXIb3RllmbCylyMrvgv0=
github.com/peterbourgon/ff/v3 v3.3.0 h1:PaKe7GW8orVFh8Unb5jNHS+JZBwWUMa2se0HM6/BI24=
github.com/peterbourgon/ff/v3 v3.3.0/go.mod h1:zjJVUhx+twciwfDl0zBcFzl4dW8axCRyXE/eKY9RztQ=
github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/rjeczalik/notify v0.9.2 h1:MiTWrPj55mNDHEiIX5YUSKefw/+lCQVoAFmD6oQm5w8=
github.com/rjeczalik/notify v0.9.2/go.mod h1:aErll2f0sUX9PXZnVNyeiObbmTlk5jnMoCa4QEjJeqM=
github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
github.com/rs/zerolog v1.29.0 h1:Zes4hju04hjbvkVkOhdl2HpZa+0PmVwigmo8XoORE5w=
github.com/rs/zerolog v1.29.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0=
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk=
Expand All @@ -47,8 +59,12 @@ golang.org/x/sys v0.0.0-20180926160741-c2ed4eda69e7/go.mod h1:STP8DvDyc/dI5b8T5h
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20200116001909-b77594299b42/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20220915200043-7b5979e65e41 h1:ohgcoMbSofXygzo6AD2I1kz3BFmW1QArPYTtwEM3UXc=
golang.org/x/sys v0.0.0-20220915200043-7b5979e65e41/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.7.0 h1:3jlCCIQZPdOYu1h8BkNvLz8Kgwtae2cagcG/VamtZRU=
golang.org/x/sys v0.7.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=
golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
Expand Down
89 changes: 89 additions & 0 deletions logging/logging.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
package logging

import (
"fmt"

"os"
"time"
"strings"

// Structured logging
"github.com/rs/zerolog"
"github.com/gin-gonic/gin"
)

var Logger zerolog.Logger

func InitLogger(level string, releaseMode bool) {
zerolog.TimeFieldFormat = time.RFC3339
// Use colorful non-JSON log output during development builds
if releaseMode {
Logger = zerolog.New(os.Stderr).With().Timestamp().Logger()
} else {
Logger = zerolog.New(
zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: "15:04:05", FormatLevel: func(i interface{}) string {
return strings.ToUpper(fmt.Sprintf("%-5s", i))
}},
).With().Timestamp().Logger()
}

switch strings.ToLower(level) {
case "error":
zerolog.SetGlobalLevel(zerolog.ErrorLevel)
case "warn":
zerolog.SetGlobalLevel(zerolog.WarnLevel)
case "info":
zerolog.SetGlobalLevel(zerolog.InfoLevel)
case "debug":
zerolog.SetGlobalLevel(zerolog.DebugLevel)
case "trace":
zerolog.SetGlobalLevel(zerolog.TraceLevel)
case "disable":
zerolog.SetGlobalLevel(zerolog.Disabled)
default:
Logger.Fatal().Msgf("error parsing commandline arguments: invalid value \"%v\" for flag -logLevel: pass one of: disable, error, warn, info, debug, trace", level)
}
}

// https://learninggolang.com/it5-gin-structured-logging.html
func GinLogger() gin.HandlerFunc {
return func(c *gin.Context) {
path := c.Request.URL.Path
raw := c.Request.URL.RawQuery

// Process request
c.Next()

// Fill the params
param := gin.LogFormatterParams{}

param.TimeStamp = time.Now() // Stop timer

param.ClientIP = c.ClientIP()
param.Method = c.Request.Method
param.StatusCode = c.Writer.Status()
param.ErrorMessage = c.Errors.ByType(gin.ErrorTypePrivate).String()
//param.Latency = duration
param.BodySize = c.Writer.Size()
if raw != "" {
path = path + "?" + raw
}
param.Path = path

// Log using the params
var logEvent *zerolog.Event
if c.Writer.Status() >= 500 {
logEvent = Logger.Error()
} else {
logEvent = Logger.Info()
}

logEvent.Str("client_id", param.ClientIP).
Str("method", param.Method).
Int("status_code", param.StatusCode).
Int("body_size", param.BodySize).
Str("path", param.Path).
//Str("latency", param.Latency.String()).
Msg(param.ErrorMessage)
}
}
29 changes: 18 additions & 11 deletions main.go
Original file line number Diff line number Diff line change
Expand Up @@ -4,19 +4,20 @@ package main

import (
"fmt"
"log"
"os"
"flag"
"sync"
"time"
"strings"
"path/filepath"

// Configuration
"github.com/peterbourgon/ff/v3"

"github.com/gin-gonic/gin"
"github.com/rjeczalik/notify" // for live-reload of manifests

"rewinged/logging"
"rewinged/models"
"rewinged/controllers"
)
Expand All @@ -40,6 +41,7 @@ func main() {
tlsCertificatePtr = fs.String("httpsCertificateFile", "./cert.pem", "The webserver certificate to use if HTTPS is enabled")
tlsPrivateKeyPtr = fs.String("httpsPrivateKeyFile", "./private.key", "The private key file to use if HTTPS is enabled")
listenAddrPtr = fs.String("listen", "localhost:8080", "The address and port for the REST API to listen on")
logLevelPtr = fs.String("logLevel", "info", "Set log verbosity: disable, error, warn, info, debug or trace")
_ = fs.String("configFile", "", "Path to a json configuration file (optional)")
)

Expand All @@ -65,7 +67,9 @@ func main() {
os.Exit(0)
}

fmt.Println("Searching for manifests...")
logging.InitLogger(*logLevelPtr, releaseMode == "true")

logging.Logger.Debug().Msg("searching for manifests")
// Start up 10 worker goroutines that can parse in manifest-files from one directory each
for w := 1; w <= 6; w++ {
go ingestManifestsWorker()
Expand All @@ -78,9 +82,9 @@ func main() {
// if manifests is just a reference-copy of manifests2 then it wouldn't be I think?
// But *currently* since live-reload isn't implemented yet, manifests2 won't be written
// to after this point so it's safe for now - TODO: only access manifests2 in a thread-safe way
fmt.Println("Found", models.Manifests.GetManifestCount(), "package manifests.")
logging.Logger.Info().Msgf("found %v package manifests", models.Manifests.GetManifestCount())

fmt.Println("Watching manifestPath for changes ...")
logging.Logger.Info().Msg("watching manifestPath for changes")
// Make the channel buffered to try and not miss events. Notify will drop
// an event if the receiver is not able to keep up the sending pace.
fileEventsBuffer := 100
Expand All @@ -91,7 +95,7 @@ func main() {
// correlate filenames to packages anyway so there's no way to know which
// package is affected by the event.
if err := notify.Watch(*packagePathPtr + "/...", fileEventsChannel, notify.Create, notify.Write); err != nil {
log.Fatal(err)
logging.Logger.Fatal().Err(err)
}
defer notify.Stop(fileEventsChannel)

Expand All @@ -104,7 +108,8 @@ func main() {
// period of time, thus necessitating further full rescans
for len(fileEventsChannel) == fileEventsBuffer {
// If the channel is ever full we are missing events as the notify package drops them at this point
log.Println("\x1b[31mfileEventsChannel full - we're missing events - will perform full manifest rescan\x1b[0m")
//log.Println("\x1b[31mfileEventsChannel full - we're missing events - will perform full manifest rescan\x1b[0m")
logging.Logger.Info().Msg("fileEventsChannel full - we're missing events - will perform full manifest rescan")
// Wait out the thundering herd - events have been lost anyway
time.Sleep(5 * time.Second)
// Drop all events to clear the channel, this also enables new events to stream in again
Expand All @@ -116,7 +121,7 @@ func main() {
}

ei := <- fileEventsChannel
log.Printf("Received event (type %T):\n\t%+v\n", ei, ei)
logging.Logger.Debug().Msgf("received event (type %T):\n\t%+v\n", ei, ei)
wg.Add(1)
jobs <- filepath.Dir(ei.Path())
}
Expand All @@ -125,21 +130,23 @@ func main() {
if releaseMode == "true" {
gin.SetMode(gin.ReleaseMode)
}
router := gin.Default()
router := gin.New()
router.SetTrustedProxies(nil)
router.Use(logging.GinLogger())
router.Use(gin.Recovery())
router.GET("/information", controllers.GetInformation)
router.GET("/packages", controllers.GetPackages)
router.POST("/manifestSearch", controllers.SearchForPackage)
router.GET("/packageManifests/:package_identifier", controllers.GetPackage)

fmt.Println("Starting server on", *listenAddrPtr)
logging.Logger.Info().Msgf("starting server on %v", *listenAddrPtr)
if *tlsEnablePtr {
if err := router.RunTLS(*listenAddrPtr, *tlsCertificatePtr, *tlsPrivateKeyPtr); err != nil {
log.Fatal("error could not start webserver:", err)
logging.Logger.Fatal().Err(err).Msg("could not start webserver")
}
} else {
if err := router.Run(*listenAddrPtr); err != nil {
log.Fatal("error could not start webserver:", err)
logging.Logger.Fatal().Err(err).Msg("could not start webserver")
}
}
}
Loading

0 comments on commit 2a5cb16

Please sign in to comment.