diff --git a/Makefile b/Makefile index fc77838..2607f73 100644 --- a/Makefile +++ b/Makefile @@ -17,6 +17,13 @@ backend_build: 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 +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: docker-compose -f ./bff/docker-compose.yaml -p df-bff up -d @@ -95,4 +102,4 @@ evans: count_lines: 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 \ No newline at end of file diff --git a/bff/gapi/logger.go b/bff/gapi/logger.go new file mode 100644 index 0000000..09be124 --- /dev/null +++ b/bff/gapi/logger.go @@ -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), + ) + } + }) +} diff --git a/bff/gapi/server.go b/bff/gapi/server.go index 6199243..912179b 100644 --- a/bff/gapi/server.go +++ b/bff/gapi/server.go @@ -2,6 +2,8 @@ package gapi import ( "fmt" + "log/slog" + "os" db "github.com/itsscb/df/bff/db/sqlc" "github.com/itsscb/df/bff/pb" @@ -29,5 +31,21 @@ func NewServer(config util.Config, store db.Store) (*Server, error) { 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 } diff --git a/bff/go.mod b/bff/go.mod index 9b49cf5..37723a0 100644 --- a/bff/go.mod +++ b/bff/go.mod @@ -60,6 +60,7 @@ require ( golang.org/x/net v0.15.0 // indirect golang.org/x/sys v0.12.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 gopkg.in/ini.v1 v1.67.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect diff --git a/bff/go.sum b/bff/go.sum index 4ca142e..f9b3e1f 100644 --- a/bff/go.sum +++ b/bff/go.sum @@ -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.4.0/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.11.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs= +golang.org/x/mod v0.12.0 h1:rmsUpXtvNzj340zd98LZ4KntptpfRHwpFOHG188oHXc= +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-20180826012351-8a410e7b638d/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-20210108195828-e2f9c7f1fc8e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA= 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.9.1/go.mod h1:owI94Op576fPu3cIGQeHs3joujW/2Oc6MtlxbF5dfNc= +golang.org/x/tools v0.13.0 h1:Iey4qkscZuv0VvIt8E0neZjtPVQFSc870HQ448QgEmQ= +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-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= diff --git a/bff/main.go b/bff/main.go index 6a2dbb9..46a8b59 100644 --- a/bff/main.go +++ b/bff/main.go @@ -6,6 +6,7 @@ import ( "embed" "io/fs" "log" + "log/slog" "net" "net/http" "time" @@ -59,12 +60,12 @@ func main() { func runDBMigration(migrationURL string, dbSource string, retries int) { migration, err := migrate.New(migrationURL, dbSource) 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 var e error - for _ = range time.Tick(3 * time.Second) { - log.Printf("retry: %d/%d\n", count, retries) + for range time.Tick(3 * time.Second) { + slog.Info("migrate db", slog.Int("retry number", count), slog.Int("max retries", retries)) migration, e = migrate.New(migrationURL, dbSource) if e == nil || count >= retries { break @@ -80,7 +81,7 @@ func runDBMigration(migrationURL string, dbSource string, retries int) { 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) { @@ -89,7 +90,8 @@ func runGRPCServer(config util.Config, store db.Store) { log.Fatalf("could not start server: %s", err) } - grpcServer := grpc.NewServer() + grpcLogger := grpc.UnaryInterceptor(gapi.GrpcLogger) + grpcServer := grpc.NewServer(grpcLogger) pb.RegisterDfServer(grpcServer, server) reflection.Register(grpcServer) @@ -98,7 +100,8 @@ func runGRPCServer(config util.Config, store db.Store) { 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) if err != nil { 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.Printf("start HTTP gateway server at %s\n", listener.Addr().String()) - err = http.Serve(listener, mux) + slog.Info("start HTTP gateway server", slog.String("address", listener.Addr().String())) + handler := gapi.HttpLogger(mux) + err = http.Serve(listener, handler) if err != nil { log.Fatal("cannot start HTTP gateway server") }