From 9de51c3925293efc91d729f7d1e2d3e3eceae893 Mon Sep 17 00:00:00 2001 From: Angel Beltran Date: Sun, 11 Jan 2026 16:54:50 -0700 Subject: [PATCH] installed logger --- go.mod | 1 + go.sum | 2 + internal/server/response/body.go | 4 +- internal/server/response/cookie.go | 4 +- internal/server/response/html.go | 4 +- internal/server/response/json.go | 4 +- internal/server/response/redirect.go | 4 +- internal/server/response/response.go | 2 +- internal/server/response/status.go | 2 +- internal/server/response/write.go | 2 +- internal/server/server.go | 69 ++++++++++++++++++++++++++-- main.go | 60 ++++++++++++++---------- 12 files changed, 116 insertions(+), 42 deletions(-) diff --git a/go.mod b/go.mod index f7d70f2..fcc4f5f 100644 --- a/go.mod +++ b/go.mod @@ -10,6 +10,7 @@ require ( github.com/angelbeltran/templater v0.1.0 github.com/coreos/go-oidc/v3 v3.8.0 github.com/google/uuid v1.5.0 + github.com/lmittmann/tint v1.1.2 github.com/oapi-codegen/runtime v1.1.2 golang.org/x/oauth2 v0.15.0 ) diff --git a/go.sum b/go.sum index c886b34..9f8fecb 100644 --- a/go.sum +++ b/go.sum @@ -89,6 +89,8 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/lib/pq v1.10.9 h1:YXG7RB+JIjhP29X+OtkiDnYaXQwpS4JEWq7dtCCRUEw= github.com/lib/pq v1.10.9/go.mod h1:AlVN5x4E4T544tWzH6hKfbfQvm3HdbOxrmggDNAPY9o= +github.com/lmittmann/tint v1.1.2 h1:2CQzrL6rslrsyjqLDwD11bZ5OpLBPU+g3G/r5LSfS8w= +github.com/lmittmann/tint v1.1.2/go.mod h1:HIS3gSy7qNwGCj+5oRjAutErFBl4BzdQP6cJZ0NfMwE= github.com/mailru/easyjson v0.7.7 h1:UGYAvKxe3sBsEDzO8ZeWOSlIQfWFlxbzLZe7hwFURr0= github.com/mailru/easyjson v0.7.7/go.mod h1:xzfreul335JAWq5oZzymOObrkdz5UnU4kGfJJLY9Nlc= github.com/mohae/deepcopy v0.0.0-20170929034955-c48cc78d4826 h1:RWengNIwukTxcDr9M+97sNutRR1RKhG96O6jWumTTnw= diff --git a/internal/server/response/body.go b/internal/server/response/body.go index 59ea17d..32f0d21 100644 --- a/internal/server/response/body.go +++ b/internal/server/response/body.go @@ -59,12 +59,12 @@ func (b bodyRes) Cookie(ck http.Cookie) Response { return Cookie(ck).wrap(b) } -func (b bodyRes) getStatus() (int, bool) { +func (b bodyRes) GetStatus() (int, bool) { if b.res == nil { return 0, false } - return b.res.getStatus() + return b.res.GetStatus() } func (b bodyRes) getRedirect() (code redirect.Code, to string, ok bool) { diff --git a/internal/server/response/cookie.go b/internal/server/response/cookie.go index b171073..c6d640c 100644 --- a/internal/server/response/cookie.go +++ b/internal/server/response/cookie.go @@ -58,12 +58,12 @@ func (c cookieRes) Cookie(ck http.Cookie) Response { return Cookie(ck).wrap(c) } -func (c cookieRes) getStatus() (int, bool) { +func (c cookieRes) GetStatus() (int, bool) { if c.res == nil { return 0, false } - return c.res.getStatus() + return c.res.GetStatus() } func (c cookieRes) getRedirect() (code redirect.Code, to string, ok bool) { diff --git a/internal/server/response/html.go b/internal/server/response/html.go index 37af3d8..b063390 100644 --- a/internal/server/response/html.go +++ b/internal/server/response/html.go @@ -60,12 +60,12 @@ func (h htmlRes) Cookie(ck http.Cookie) Response { return Cookie(ck).wrap(h) } -func (h htmlRes) getStatus() (int, bool) { +func (h htmlRes) GetStatus() (int, bool) { if h.res == nil { return 0, false } - return h.res.getStatus() + return h.res.GetStatus() } func (h htmlRes) getRedirect() (code redirect.Code, to string, ok bool) { diff --git a/internal/server/response/json.go b/internal/server/response/json.go index cfc0115..b2d3223 100644 --- a/internal/server/response/json.go +++ b/internal/server/response/json.go @@ -61,12 +61,12 @@ func (j jsonRes) Cookie(ck http.Cookie) Response { return Cookie(ck).wrap(j) } -func (j jsonRes) getStatus() (int, bool) { +func (j jsonRes) GetStatus() (int, bool) { if j.res == nil { return 0, false } - return j.res.getStatus() + return j.res.GetStatus() } func (j jsonRes) getRedirect() (code redirect.Code, to string, ok bool) { diff --git a/internal/server/response/redirect.go b/internal/server/response/redirect.go index ad25948..1ff2d2c 100644 --- a/internal/server/response/redirect.go +++ b/internal/server/response/redirect.go @@ -99,12 +99,12 @@ func (r redirectRes) Cookie(ck http.Cookie) Response { return Cookie(ck).wrap(r) } -func (r redirectRes) getStatus() (int, bool) { +func (r redirectRes) GetStatus() (int, bool) { if r.res == nil { return 0, false } - return r.res.getStatus() + return r.res.GetStatus() } func (r redirectRes) getRedirect() (code redirect.Code, to string, ok bool) { diff --git a/internal/server/response/response.go b/internal/server/response/response.go index 1991ac2..858972c 100644 --- a/internal/server/response/response.go +++ b/internal/server/response/response.go @@ -16,7 +16,7 @@ type ( JSON(any) Response Cookie(http.Cookie) Response - getStatus() (code int, ok bool) + GetStatus() (code int, ok bool) getBody() (body io.ReadCloser, ok bool, err error) getRedirect() (code redirect.Code, to string, ok bool) getCookies() []http.Cookie diff --git a/internal/server/response/status.go b/internal/server/response/status.go index 51d0730..f4dd685 100644 --- a/internal/server/response/status.go +++ b/internal/server/response/status.go @@ -60,7 +60,7 @@ func (s statusRes) Cookie(ck http.Cookie) Response { return Cookie(ck).wrap(s) } -func (s statusRes) getStatus() (int, bool) { +func (s statusRes) GetStatus() (int, bool) { return s.code, true } diff --git a/internal/server/response/write.go b/internal/server/response/write.go index be95f2a..5688a97 100644 --- a/internal/server/response/write.go +++ b/internal/server/response/write.go @@ -36,7 +36,7 @@ func Write(w http.ResponseWriter, r *http.Request, res Response) { return } - if status, ok := res.getStatus(); ok { + if status, ok := res.GetStatus(); ok { w.WriteHeader(status) } if bodySet { diff --git a/internal/server/server.go b/internal/server/server.go index afb0c2c..ab1595d 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -1,6 +1,7 @@ package server import ( + "context" "encoding/json" "fmt" "html/template" @@ -9,6 +10,7 @@ import ( "path" "strconv" "strings" + "time" "github.com/angelbeltran/templater" @@ -36,6 +38,7 @@ type Server struct { } func NewServer( + ctx context.Context, logger *slog.Logger, contentDir string, rawEvents *raw_events.Store, @@ -43,14 +46,49 @@ func NewServer( etsy *etsy_platform.Platform, auth *authentication.Authenticator, ) *Server { + reqIDCh := newRequestIDProvider(ctx) + + reqLog := logger.WithGroup("request") mux := response.NewMux(func(fn response.HandlerFunc) response.HandlerFunc { return func(r *http.Request) (response.Response, error) { - res, err := fn(r) - if err != nil { - status := response.GetStatusFromError(err) + start := time.Now() - // TODO: get better logger - fmt.Printf("[ERROR]: %d: %s; %s\n", status, r.URL, err) + args := []any{ + "id", <-reqIDCh, + "url", r.URL, + } + + reqLog.Debug("Request", args...) + + res, err := fn(r) + end := time.Now() + + var status int + if err != nil { + status = response.GetStatusFromError(err) + } else { + var ok bool + if status, ok = res.GetStatus(); !ok { + status = http.StatusOK + } + } + + args = append(args, + "status", status, + "elapsed", time.Duration(end.UnixNano()-start.UnixNano()), + ) + + switch status / 100 { + case 1: + reqLog.Debug("Response", args...) + case 2: + reqLog.Debug("Response", args...) + case 3: + reqLog.Debug("Response", args...) + case 4: + reqLog.Warn("Response", args...) + default: + reqLog.Error("Response", args...) } return res, err @@ -223,3 +261,24 @@ func mapConstantErrorsToHTTPErrors(err error) error { } return err } + +func newRequestIDProvider(ctx context.Context) <-chan int { + reqIDCh := make(chan int) + + go func() { + defer close(reqIDCh) + + nextReqID := 1 + + for { + select { + case reqIDCh <- nextReqID: + nextReqID += 1 + case <-ctx.Done(): + return + } + } + }() + + return reqIDCh +} diff --git a/main.go b/main.go index 08c8cdc..45a2621 100644 --- a/main.go +++ b/main.go @@ -13,10 +13,12 @@ import ( "net/http" "os" "os/signal" + "strings" "syscall" "time" "github.com/jackc/pgx/v5/pgxpool" + "github.com/lmittmann/tint" "ruben/inventory2/internal/domains/accounts" "ruben/inventory2/internal/domains/authentication" @@ -31,27 +33,36 @@ const ( ) func main() { - if err := runApp(context.Background()); err != nil { - panic(err) - } - fmt.Println("application shutdown") -} - -func runApp(ctx context.Context) error { - ctx, shutdown := context.WithCancel(ctx) - defer shutdown() - - logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ + logger := slog.New(tint.NewHandler(os.Stderr, &tint.Options{ AddSource: true, Level: slog.LevelDebug, ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { - fmt.Println("slog groups:", groups) - fmt.Println("slog attr:", a) - // TODO: not sure if this will be needed, but keep around until known. + // this can perform general key=value log cleanup + + if a.Key == slog.SourceKey && len(groups) == 0 { + source := a.Value.Any().(*slog.Source) + source.File = strings.TrimPrefix(source.File, "/home/angel/go/src/ruben/inventory2/internal") + } + return a }, + // Time format (Default: time.StampMilli) + //TimeFormat: "", })) + logger.Info("application starting") + + if err := runApp(context.Background(), logger); err != nil { + panic(err) + } + + logger.Info("application shutdown") +} + +func runApp(ctx context.Context, logger *slog.Logger) error { + ctx, shutdown := context.WithCancel(ctx) + defer shutdown() + // connect to the database connPool, err := newPool(ctx) @@ -61,7 +72,7 @@ func runApp(ctx context.Context) error { // start background processes - auth, err := authentication.New(ctx, connPool, logger.WithGroup("*authentication.Authenticator")) + auth, err := authentication.New(ctx, connPool, logger.WithGroup("authenticator")) if err != nil { return fmt.Errorf("failed to construct authenticator: %w", err) } @@ -85,19 +96,19 @@ func runApp(ctx context.Context) error { ) select { case s := <-osSignalCh: - fmt.Println("application received shutdown signal:", s) - fmt.Println("shutting down") + logger.Info("application received shutdown signal", "signal", s) + logger.Info("shutting down") case err := <-authErrCh: alreadyShutdown.authProcesses = true - fmt.Println("auth processes shutdown unexpectedly") + logger.Error("auth processes shutdown unexpectedly") if err != nil { - fmt.Println("auth processes encountered error:", err) + logger.Error("auth processes encountered error", "error", err) } case err := <-srvErrCh: alreadyShutdown.server = true - fmt.Println("server shutdown unexpectedly") + logger.Error("server shutdown unexpectedly") if err != nil { - fmt.Println("server encountered error:", err) + logger.Error("server encountered error", "error", err) } } @@ -111,14 +122,14 @@ func runApp(ctx context.Context) error { if err := <-authErrCh; err != nil { errs = append(errs, fmt.Errorf("auth processes experienced an error: %w", err)) } - fmt.Println("auth processes shut down") + logger.Info("auth processes shut down") } if !alreadyShutdown.server { if err := <-srvErrCh; err != nil { errs = append(errs, fmt.Errorf("server experienced an error: %w", err)) } - fmt.Println("server shut down") + logger.Info("server shut down") } return errors.Join(errs...) @@ -141,6 +152,7 @@ func runServer(ctx context.Context, logger *slog.Logger, connPool *pgxpool.Pool, srv := &http.Server{ Addr: ":8082", // local Handler: server.NewServer( + ctx, logger.WithGroup("server"), "./", raw_events.NewStore(logger.WithGroup("raw-event-store"), connPool), @@ -167,7 +179,7 @@ func runServer(ctx context.Context, logger *slog.Logger, connPool *pgxpool.Pool, defer cancel() defer close(alreadyShutdownCh) - fmt.Println("server running on 8082...") + logger.Info("server running on 8082...") if err := srv.ListenAndServe(); err != nil { if !errors.Is(err, http.ErrServerClosed) { runningErrCh <- fmt.Errorf("server experienced error: %w", err)