From 828d38639c5ddc1df1c6e9631a37d327a3f67cdf Mon Sep 17 00:00:00 2001 From: Ben Visness Date: Wed, 10 Mar 2021 21:19:39 -0600 Subject: [PATCH] Add structured logging --- .gitignore | 1 + color/color.go | 49 ++++++++++++++ config/types.go | 1 + db/db.go | 6 +- logging/logging.go | 158 +++++++++++++++++++++++++++++++++++++++++++++ oops/oops.go | 20 +++++- website/website.go | 19 ++++-- 7 files changed, 245 insertions(+), 9 deletions(-) create mode 100644 color/color.go create mode 100644 logging/logging.go diff --git a/.gitignore b/.gitignore index fc6cb089..cdee5c0c 100644 --- a/.gitignore +++ b/.gitignore @@ -1 +1,2 @@ config/config.go +.vscode diff --git a/color/color.go b/color/color.go new file mode 100644 index 00000000..f2d23d6b --- /dev/null +++ b/color/color.go @@ -0,0 +1,49 @@ +package color + +import "runtime" + +// See this file for a good color reference: +// https://github.com/fatih/color/blob/master/color.go + +var Reset = "\033[0m" +var Bold = "\033[1m" +var Faint = "\033[2m" +var Italic = "\033[3m" +var Underline = "\033[4m" +var BlinkSlow = "\033[5m" +var BlinkRapid = "\033[6m" +var ReverseVideo = "\033[7m" +var Concealed = "\033[8m" +var CrossedOut = "\033[9m" + +var Red = "\033[31m" +var Green = "\033[32m" +var Yellow = "\033[33m" +var Blue = "\033[34m" +var Purple = "\033[35m" +var Cyan = "\033[36m" +var Gray = "\033[37m" +var White = "\033[97m" + +var BgBlack = "\033[40m" +var BgRed = "\033[41m" +var BgGreen = "\033[42m" +var BgYellow = "\033[43m" +var BgBlue = "\033[44m" +var BgMagenta = "\033[45m" +var BgCyan = "\033[46m" +var BgWhite = "\033[47m" + +func init() { + if runtime.GOOS == "windows" { + Reset = "" + Red = "" + Green = "" + Yellow = "" + Blue = "" + Purple = "" + Cyan = "" + Gray = "" + White = "" + } +} diff --git a/config/types.go b/config/types.go index 78b42e2b..ab18b765 100644 --- a/config/types.go +++ b/config/types.go @@ -12,6 +12,7 @@ const ( type HMNConfig struct { Env Environment + Addr string Postgres PostgresConfig } diff --git a/db/db.go b/db/db.go index 15adddbf..56e12978 100644 --- a/db/db.go +++ b/db/db.go @@ -2,9 +2,9 @@ package db import ( "context" - "fmt" "git.handmade.network/hmn/hmn/config" + "git.handmade.network/hmn/hmn/oops" "github.com/jackc/pgx/v4" "github.com/jackc/pgx/v4/pgxpool" ) @@ -12,7 +12,7 @@ import ( func NewConn() *pgx.Conn { conn, err := pgx.Connect(context.Background(), config.Config.Postgres.DSN()) if err != nil { - panic(fmt.Errorf("failed to create database connection: %w", err)) + panic(oops.New(err, "failed to connect to database")) } return conn @@ -26,7 +26,7 @@ func NewConnPool(minConns, maxConns int32) *pgxpool.Pool { conn, err := pgxpool.ConnectConfig(context.Background(), config) if err != nil { - panic(fmt.Errorf("failed to create database connection pool: %w", err)) + panic(oops.New(err, "failed to create database connection pool")) } return conn diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 00000000..34045e5f --- /dev/null +++ b/logging/logging.go @@ -0,0 +1,158 @@ +package logging + +import ( + "encoding/json" + "os" + "sort" + "strconv" + "strings" + + "git.handmade.network/hmn/hmn/color" + "git.handmade.network/hmn/hmn/oops" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +func init() { + zerolog.ErrorStackMarshaler = oops.ZerologStackMarshaler + log.Logger = log.Output(NewPrettyZerologWriter()) +} + +func Trace() *zerolog.Event { + return log.Trace().Timestamp().Stack() +} + +func Debug() *zerolog.Event { + return log.Debug().Timestamp().Stack() +} + +func Info() *zerolog.Event { + return log.Info().Timestamp().Stack() +} + +func Warn() *zerolog.Event { + return log.Warn().Timestamp().Stack() +} + +func Error() *zerolog.Event { + return log.Error().Timestamp().Stack() +} + +type PrettyZerologWriter struct { + wd string +} + +type PrettyLogEntry struct { + Timestamp string + Level string + Message string + Error string + StackTrace []interface{} + + OtherFields []PrettyField +} + +type PrettyField struct { + Name string + Value interface{} +} + +var ColorFromLevel = map[string]string{ + "trace": color.Gray, + "debug": color.Gray, + "info": color.BgBlue, + "warn": color.BgYellow, + "error": color.BgRed, + "fatal": color.BgRed, + "panic": color.BgRed, +} + +func NewPrettyZerologWriter() *PrettyZerologWriter { + wd, _ := os.Getwd() + return &PrettyZerologWriter{ + wd: wd, + } +} + +func (w *PrettyZerologWriter) Write(p []byte) (int, error) { + // TODO: panic recovery so we log _something_ + + var fields map[string]interface{} + err := json.Unmarshal(p, &fields) + if err != nil { + return os.Stderr.Write(p) + } + + var pretty PrettyLogEntry + for name, val := range fields { + switch name { + case zerolog.TimestampFieldName: + pretty.Timestamp = val.(string) + case zerolog.LevelFieldName: + pretty.Level = val.(string) + case zerolog.MessageFieldName: + pretty.Message = val.(string) + case zerolog.ErrorFieldName: + pretty.Error = val.(string) + case zerolog.ErrorStackFieldName: + pretty.StackTrace = val.([]interface{}) + default: + pretty.OtherFields = append(pretty.OtherFields, PrettyField{ + Name: name, + Value: val, + }) + } + } + + sort.Slice(pretty.OtherFields, func(i, j int) bool { + return strings.Compare(pretty.OtherFields[i].Name, pretty.OtherFields[j].Name) < 0 + }) + + var b strings.Builder + b.WriteString("---------------------------------------\n") + b.WriteString(pretty.Timestamp) + b.WriteString(" ") + if pretty.Level != "" { + b.WriteString(ColorFromLevel[pretty.Level]) + b.WriteString(color.Bold) + b.WriteString(strings.ToUpper(pretty.Level)) + b.WriteString(color.Reset) + b.WriteString(": ") + } + b.WriteString(pretty.Message) + b.WriteString("\n") + if pretty.Error != "" { + b.WriteString(" " + color.Bold + color.Red + "ERROR:" + color.Reset + " ") + b.WriteString(pretty.Error) + b.WriteString("\n") + } + if len(pretty.OtherFields) > 0 { + b.WriteString(" " + color.Bold + color.Blue + "Fields:" + color.Reset + "\n") + for _, field := range pretty.OtherFields { + valuePretty, _ := json.MarshalIndent(field.Value, " ", " ") + b.WriteString(" ") + b.WriteString(field.Name) + b.WriteString(": ") + b.WriteString(string(valuePretty)) + b.WriteString("\n") + } + } + if pretty.StackTrace != nil { + b.WriteString(" " + color.Bold + color.Blue + "Stack trace:" + color.Reset + "\n") + for _, frame := range pretty.StackTrace { + frameMap := frame.(map[string]interface{}) + file := frameMap["file"].(string) + file = strings.Replace(file, w.wd, ".", 1) + + b.WriteString(" ") + b.WriteString(frameMap["function"].(string)) + b.WriteString(" (") + b.WriteString(file) + b.WriteString(":") + b.WriteString(strconv.Itoa(int(frameMap["line"].(float64)))) + b.WriteString(")\n") + } + } + + return os.Stderr.Write([]byte(b.String())) +} diff --git a/oops/oops.go b/oops/oops.go index f5d2e6cd..a660460a 100644 --- a/oops/oops.go +++ b/oops/oops.go @@ -4,12 +4,13 @@ import ( "fmt" "github.com/go-stack/stack" + "github.com/rs/zerolog" ) type Error struct { Message string Wrapped error - Stack []StackFrame + Stack CallStack } func (e *Error) Error() string { @@ -20,12 +21,27 @@ func (e *Error) Unwrap() error { return e.Wrapped } +type CallStack []StackFrame + +func (s CallStack) MarshalZerologArray(a *zerolog.Array) { + for _, frame := range s { + a.Object(frame) + } +} + type StackFrame struct { File string `json:"file"` Line int `json:"line"` Function string `json:"function"` } +func (f StackFrame) MarshalZerologObject(e *zerolog.Event) { + e. + Str("file", f.File). + Int("line", f.Line). + Str("function", f.Function) +} + var ZerologStackMarshaler = func(err error) interface{} { if asOops, ok := err.(*Error); ok { return asOops.Stack @@ -35,7 +51,7 @@ var ZerologStackMarshaler = func(err error) interface{} { func New(wrapped error, format string, args ...interface{}) error { trace := stack.Trace().TrimRuntime() - frames := make([]StackFrame, len(trace)) + frames := make(CallStack, len(trace)) for i, call := range trace { callFrame := call.Frame() frames[i] = StackFrame{ diff --git a/website/website.go b/website/website.go index 744ac319..9dc94d6c 100644 --- a/website/website.go +++ b/website/website.go @@ -3,10 +3,11 @@ package website import ( "context" "fmt" - "log" "net/http" + "git.handmade.network/hmn/hmn/config" "git.handmade.network/hmn/hmn/db" + "git.handmade.network/hmn/hmn/logging" "github.com/julienschmidt/httprouter" "github.com/spf13/cobra" ) @@ -14,7 +15,17 @@ import ( var WebsiteCommand = &cobra.Command{ Short: "Run the HMN website", Run: func(cmd *cobra.Command, args []string) { - fmt.Println("Hello, HMN!") + defer func() { + if r := recover(); r != nil { + if err, ok := r.(error); ok { + logging.Error().Err(err).Msg("recovered from panic") + } else { + logging.Error().Interface("recovered", r).Msg("recovered from panic") + } + } + }() + + logging.Info().Msg("Hello, HMN!") conn := db.NewConnPool(4, 8) @@ -33,7 +44,7 @@ var WebsiteCommand = &cobra.Command{ rw.Write([]byte(fmt.Sprintf("(%s) %s\n", id, name))) }) - log.Print("serving stuff") - http.ListenAndServe(":9001", router) + logging.Info().Str("addr", config.Config.Addr).Msg("Serving the website") + http.ListenAndServe(config.Config.Addr, router) }, }