Add logger to gRPC and -gateway

Fixes #74
This commit is contained in:
itsscb 2023-10-08 00:26:02 +02:00
parent 71da81d6ca
commit 58c2e317c6
6 changed files with 142 additions and 13 deletions

View File

@ -17,6 +17,13 @@ backend_build:
docker exec -it postgres createdb --username=root --owner=root df docker exec -it postgres createdb --username=root --owner=root df
docker run --name migrateup --rm --privileged=true -v $(PWD)/bff/db/migration:/migrations --network host migrate/migrate -path=/migrations/ -database $(DB_URL) up docker run --name migrateup --rm --privileged=true -v $(PWD)/bff/db/migration:/migrations --network host migrate/migrate -path=/migrations/ -database $(DB_URL) up
rebuild:
docker stop df-bff_api_1
docker stop df-bff_postgres_1
docker rm df-bff_api_1
docker rmi df-bff_api
make backend
backend: backend:
docker-compose -f ./bff/docker-compose.yaml -p df-bff up -d docker-compose -f ./bff/docker-compose.yaml -p df-bff up -d
@ -95,4 +102,4 @@ evans:
count_lines: count_lines:
cloc --exclude-dir=.history,.git . cloc --exclude-dir=.history,.git .
.PHONY: postgres migratenew createdb dropdb migrateup migratedown sqlc sqlcinit test server backend_build backend backend-stop reset_docker proto evans count_lines .PHONY: reset_docker backend_build rebuild backend backend dev network postgres migratenew migrateup migratedown createdb dropdb sqlc sqlcinit test coverage server mock proto evans count_lines

99
bff/gapi/logger.go Normal file
View File

@ -0,0 +1,99 @@
package gapi
import (
"context"
"log/slog"
"net/http"
"time"
"google.golang.org/grpc"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
)
func GrpcLogger(
ctx context.Context,
req interface{},
info *grpc.UnaryServerInfo,
handler grpc.UnaryHandler,
) (resp interface{}, err error) {
startTime := time.Now()
result, err := handler(ctx, req)
duration := time.Since(startTime)
statusCode := codes.Unknown
if st, ok := status.FromError(err); ok {
statusCode = st.Code()
}
if err != nil {
slog.Error("received a gRPC request",
slog.String("protocol", "grpc"),
slog.String("endpoint", info.FullMethod),
slog.Int("status_code", int(statusCode)),
slog.String("status_text", statusCode.String()),
slog.Duration("duration", duration),
slog.String("error", err.Error()),
)
} else {
slog.Info("received a gRPC request",
slog.String("protocol", "grpc"),
slog.String("endpoint", info.FullMethod),
slog.Int("status_code", int(statusCode)),
slog.String("status_text", statusCode.String()),
slog.Duration("duration", duration),
)
}
return result, err
}
type ResponseRecorder struct {
http.ResponseWriter
StatusCode int
Body []byte
}
func (rec *ResponseRecorder) WriteHeader(statusCode int) {
rec.StatusCode = statusCode
rec.ResponseWriter.WriteHeader(statusCode)
}
func (rec *ResponseRecorder) Write(body []byte) (int, error) {
rec.Body = body
return rec.ResponseWriter.Write(body)
}
func HttpLogger(handler http.Handler) http.Handler {
return http.HandlerFunc(func(res http.ResponseWriter, req *http.Request) {
startTime := time.Now()
rec := &ResponseRecorder{
ResponseWriter: res,
StatusCode: http.StatusOK,
}
handler.ServeHTTP(rec, req)
duration := time.Since(startTime)
if rec.StatusCode != http.StatusOK {
slog.Error("received a HTTP request",
slog.String("protocol", "http"),
slog.String("method", req.Method),
slog.String("endpoint", req.RequestURI),
slog.Int("status_code", rec.StatusCode),
slog.String("status_text", http.StatusText(rec.StatusCode)),
slog.Duration("duration", duration),
slog.String("body", string(rec.Body)),
)
} else {
slog.Info("received a HTTP request",
slog.String("protocol", "http"),
slog.String("method", req.Method),
slog.String("endpoint", req.RequestURI),
slog.Int("status_code", rec.StatusCode),
slog.String("status_text", http.StatusText(rec.StatusCode)),
slog.Duration("duration", duration),
)
}
})
}

View File

@ -2,6 +2,8 @@ package gapi
import ( import (
"fmt" "fmt"
"log/slog"
"os"
db "github.com/itsscb/df/bff/db/sqlc" db "github.com/itsscb/df/bff/db/sqlc"
"github.com/itsscb/df/bff/pb" "github.com/itsscb/df/bff/pb"
@ -29,5 +31,21 @@ func NewServer(config util.Config, store db.Store) (*Server, error) {
tokenMaker: tokenMaker, tokenMaker: tokenMaker,
} }
logLevel := slog.LevelError
if config.Environment == "development" {
logLevel = slog.LevelDebug
}
opts := slog.HandlerOptions{
Level: logLevel,
}
logger := slog.New(slog.NewTextHandler(os.Stdout, &opts))
if config.LogOutput == "json" {
logger = slog.New(slog.NewJSONHandler(os.Stdout, &opts))
}
slog.SetDefault(logger)
return server, nil return server, nil
} }

View File

@ -60,6 +60,7 @@ require (
golang.org/x/net v0.15.0 // indirect golang.org/x/net v0.15.0 // indirect
golang.org/x/sys v0.12.0 // indirect golang.org/x/sys v0.12.0 // indirect
golang.org/x/text v0.13.0 // indirect golang.org/x/text v0.13.0 // indirect
golang.org/x/tools v0.13.0 // indirect
google.golang.org/genproto v0.0.0-20230803162519-f966b187b2e5 // indirect google.golang.org/genproto v0.0.0-20230803162519-f966b187b2e5 // indirect
gopkg.in/ini.v1 v1.67.0 // indirect gopkg.in/ini.v1 v1.67.0 // indirect
gopkg.in/yaml.v3 v3.0.1 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect

View File

@ -330,8 +330,8 @@ golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
golang.org/x/mod v0.4.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.4.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
golang.org/x/mod v0.4.1/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= golang.org/x/mod v0.4.1/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
golang.org/x/mod v0.11.0 h1:bUO06HqtnRcc/7l71XBe4WcqTZ+3AH1J59zWDDwLKgU= golang.org/x/mod v0.12.0 h1:rmsUpXtvNzj340zd98LZ4KntptpfRHwpFOHG188oHXc=
golang.org/x/mod v0.11.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs= golang.org/x/mod v0.12.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs=
golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
golang.org/x/net v0.0.0-20190108225652-1e06a53dbb7e/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20190108225652-1e06a53dbb7e/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
@ -486,8 +486,8 @@ golang.org/x/tools v0.0.0-20201208233053-a543418bbed2/go.mod h1:emZCQorbCU4vsT4f
golang.org/x/tools v0.0.0-20210105154028-b0ab187a4818/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA= golang.org/x/tools v0.0.0-20210105154028-b0ab187a4818/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20210108195828-e2f9c7f1fc8e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA= golang.org/x/tools v0.0.0-20210108195828-e2f9c7f1fc8e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0= golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0=
golang.org/x/tools v0.9.1 h1:8WMNJAz3zrtPmnYC7ISf5dEn3MT0gY7jBJfw27yrrLo= golang.org/x/tools v0.13.0 h1:Iey4qkscZuv0VvIt8E0neZjtPVQFSc870HQ448QgEmQ=
golang.org/x/tools v0.9.1/go.mod h1:owI94Op576fPu3cIGQeHs3joujW/2Oc6MtlxbF5dfNc= golang.org/x/tools v0.13.0/go.mod h1:HvlwmtVNQAhOuCjW7xxvovg8wbNq7LwfXh/k7wXUl58=
golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

View File

@ -6,6 +6,7 @@ import (
"embed" "embed"
"io/fs" "io/fs"
"log" "log"
"log/slog"
"net" "net"
"net/http" "net/http"
"time" "time"
@ -59,12 +60,12 @@ func main() {
func runDBMigration(migrationURL string, dbSource string, retries int) { func runDBMigration(migrationURL string, dbSource string, retries int) {
migration, err := migrate.New(migrationURL, dbSource) migration, err := migrate.New(migrationURL, dbSource)
if err != nil { if err != nil {
log.Printf("could not create migrate instance. Retrying %d more times...\n", retries) slog.Warn("could not migrate db instance. Retrying...")
count := 1 count := 1
var e error var e error
for _ = range time.Tick(3 * time.Second) { for range time.Tick(3 * time.Second) {
log.Printf("retry: %d/%d\n", count, retries) slog.Info("migrate db", slog.Int("retry number", count), slog.Int("max retries", retries))
migration, e = migrate.New(migrationURL, dbSource) migration, e = migrate.New(migrationURL, dbSource)
if e == nil || count >= retries { if e == nil || count >= retries {
break break
@ -80,7 +81,7 @@ func runDBMigration(migrationURL string, dbSource string, retries int) {
log.Fatal("failed to run migrate up") log.Fatal("failed to run migrate up")
} }
log.Println("db migrated successfully") slog.Info("db migrated successfully")
} }
func runGRPCServer(config util.Config, store db.Store) { func runGRPCServer(config util.Config, store db.Store) {
@ -89,7 +90,8 @@ func runGRPCServer(config util.Config, store db.Store) {
log.Fatalf("could not start server: %s", err) log.Fatalf("could not start server: %s", err)
} }
grpcServer := grpc.NewServer() grpcLogger := grpc.UnaryInterceptor(gapi.GrpcLogger)
grpcServer := grpc.NewServer(grpcLogger)
pb.RegisterDfServer(grpcServer, server) pb.RegisterDfServer(grpcServer, server)
reflection.Register(grpcServer) reflection.Register(grpcServer)
@ -98,7 +100,8 @@ func runGRPCServer(config util.Config, store db.Store) {
log.Fatal("cannot create gRPC server:", err) log.Fatal("cannot create gRPC server:", err)
} }
log.Printf("start gRPC server at %s", listener.Addr().String()) slog.Info("start gRPC server", slog.String("address", listener.Addr().String()))
err = grpcServer.Serve(listener) err = grpcServer.Serve(listener)
if err != nil { if err != nil {
log.Fatal("cannot start gRPC server:", err) log.Fatal("cannot start gRPC server:", err)
@ -142,8 +145,9 @@ func runGatewayServer(config util.Config, store db.Store, swaggerFS http.FileSys
log.Fatal("cannot create listener") log.Fatal("cannot create listener")
} }
log.Printf("start HTTP gateway server at %s\n", listener.Addr().String()) slog.Info("start HTTP gateway server", slog.String("address", listener.Addr().String()))
err = http.Serve(listener, mux) handler := gapi.HttpLogger(mux)
err = http.Serve(listener, handler)
if err != nil { if err != nil {
log.Fatal("cannot start HTTP gateway server") log.Fatal("cannot start HTTP gateway server")
} }