From 8fedb6c4a92159797fcd4a7ca215d558b151c380 Mon Sep 17 00:00:00 2001 From: Tyler Gabb Date: Sun, 2 Mar 2025 19:55:10 -0700 Subject: [PATCH] logging improvements --- examples/proxy/proxy.go | 3 +- examples/server/impl/intbidi.go | 33 ++---- examples/server/impl/serverstream.go | 11 +- internal/logging/logging.go | 145 +++++++++++++++++++++++++++ 4 files changed, 168 insertions(+), 24 deletions(-) create mode 100644 internal/logging/logging.go diff --git a/examples/proxy/proxy.go b/examples/proxy/proxy.go index 7729ab0..1f90837 100644 --- a/examples/proxy/proxy.go +++ b/examples/proxy/proxy.go @@ -2,6 +2,7 @@ package main import ( "flag" + "google.golang.org/grpc/credentials/insecure" server "github.com/TylerJGabb/grpc-http-proxy/examples/server/impl" @@ -10,7 +11,7 @@ import ( func main() { exampleServer := server.ExampleServer{} - addr := exampleServer.Start(9091) + addr := exampleServer.Start(9092) port := flag.Int("port", 8080, "the port number") flag.Parse() diff --git a/examples/server/impl/intbidi.go b/examples/server/impl/intbidi.go index 0146d9c..20cb711 100644 --- a/examples/server/impl/intbidi.go +++ b/examples/server/impl/intbidi.go @@ -1,10 +1,7 @@ package server import ( - "context" - "fmt" - "io" - + "github.com/TylerJGabb/grpc-http-proxy/internal/logging" "github.com/TylerJGabb/grpc-http-proxy/pkg/tgsbpb" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" @@ -13,50 +10,42 @@ import ( func (s *ExampleServer) BidirectionalStreamInt( stream tgsbpb.TylerSandboxService_BidirectionalStreamIntServer, ) error { - // when we return out of this method, the context of the stream will be canceled - ctx, cancel := context.WithCancel(stream.Context()) - defer cancel() + logger := logging.NewLogger(logging.WithOperationId("server.BidirectionalStreamInt")) + logger.Info("stream starting") in := make(chan *tgsbpb.BidirectionalStreamIntRequest) - errs := make(chan error, 1) go func() { + defer logger.Info("server receive goroutine ended") for { // this is a blocking call, will unblock when stream context is canceled msg, err := stream.Recv() if err != nil { - if err == io.EOF { - cancel() - } else { - fmt.Printf("receive error: %s\n", err.Error()) - errs <- err - } + logger.Info("error while receiving from stream", "err", err) return } select { case in <- msg: - case <-ctx.Done(): + case <-stream.Context().Done(): return } } }() for { select { - case err := <-errs: - return err - case <-ctx.Done(): + case <-stream.Context().Done(): return nil case req := <-in: if req.Close { - cancel() + logger.Info("server is closing the stream intentionally") return status.Error(codes.Canceled, "stream closed intentionally") } if req.RespondWithError { + logger.Info("server is intentionally returning error") return status.Error(codes.Internal, "error returned intentionally") } send := &tgsbpb.BidirectionalStreamIntResponse{Value: req.Value} - // this is a blocking call, will unblock when stream context is canceled + logger.Info("sending response", "value", send.Value) if err := stream.Send(send); err != nil { - fmt.Printf("send error: %s\n", err.Error()) - return err + logger.Info("unexpected error while sending on stream", "err", err) } } } diff --git a/examples/server/impl/serverstream.go b/examples/server/impl/serverstream.go index 53b5781..f76f54f 100644 --- a/examples/server/impl/serverstream.go +++ b/examples/server/impl/serverstream.go @@ -2,7 +2,9 @@ package server import ( "fmt" + "log/slog" "math" + "os" "time" "github.com/TylerJGabb/grpc-http-proxy/pkg/tgsbpb" @@ -14,24 +16,31 @@ func (s *ExampleServer) ServerStreamInt( req *tgsbpb.ServerStreamIntRequest, stream tgsbpb.TylerSandboxService_ServerStreamIntServer, ) error { + logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{})).With("method", "ServerStreamInt") req.SendPeriodSeconds = uint32(math.Max(float64(req.SendPeriodSeconds), 1)) if req.SendErrorAtNthResponse == 0 { + logger.Info("SendErrorAtNthResponse is 0, will never send an error") req.SendErrorAtNthResponse = math.MaxUint32 } if req.CloseAtNthResponse == 0 { + logger.Info("CloseAtNthResponse is 0, will never close the stream") req.CloseAtNthResponse = math.MaxUint32 } var responseCount uint32 = 1 + defer logger.Info("stream ended") for { time.Sleep(time.Second * time.Duration(req.SendPeriodSeconds)) if responseCount >= req.CloseAtNthResponse { + logger.Info("server is ending the stream") return nil } if responseCount >= req.SendErrorAtNthResponse { + logger.Error("server is intentionally returning error") return status.Error(codes.Internal, "intentionally returned error") } + logger.Info("sending response", "responseCount", responseCount, "value", req.Value) if err := stream.Send(&tgsbpb.ServerStreamIntResponse{Value: req.Value}); err != nil { - fmt.Println(err.Error()) + logger.Info("unexpected error while sending on stream", "err", err) return status.Error(codes.Internal, err.Error()) } responseCount++ diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 0000000..c2a8684 --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,145 @@ +package logging + +import ( + "io" + "log/slog" + "os" +) + +// structuredLoggingEnvVar logging off by default +var structuredLoggingEnvVar bool = false + +// loggingLevelEnvVar default logging level is info +var loggingLevelEnvVar slog.Level = slog.LevelInfo + +func init() { + if os.Getenv("STRUCTURED_LOGGING") == "on" { + structuredLoggingEnvVar = true + } + if logLevel := os.Getenv("LOG_LEVEL"); logLevel != "" { + loggingLevelEnvVar.UnmarshalText([]byte(logLevel)) + } +} + +type LoggerOptions struct { + requestId string + operationId string + attributes map[string]string + output io.Writer + structured bool + logLevel slog.Level +} +type LoggerOptionFuction func(*LoggerOptions) + +func WithAttribute(key, value string) LoggerOptionFuction { + return func(l *LoggerOptions) { + l.attributes[key] = value + } +} + +func WithRequestId(requestId string) LoggerOptionFuction { + return func(l *LoggerOptions) { + l.requestId = requestId + } +} + +func WithOperationId(operationId string) LoggerOptionFuction { + return func(l *LoggerOptions) { + l.operationId = operationId + } +} + +func WithOutput(w io.Writer) LoggerOptionFuction { + return func(l *LoggerOptions) { + l.output = w + } +} + +func WithStructuredLogging(enabled bool) LoggerOptionFuction { + return func(l *LoggerOptions) { + l.structured = enabled + } +} + +func WithLogLevel(level slog.Level) LoggerOptionFuction { + return func(l *LoggerOptions) { + l.logLevel = level + } +} + +func (l *LoggerOptions) Attrs() []slog.Attr { + attrs := make([]slog.Attr, 0) + if l.requestId != "" { + attrs = append(attrs, slog.Attr{ + Key: "requestId", + Value: slog.StringValue(l.requestId), + }) + } + if l.operationId != "" { + attrs = append(attrs, slog.Attr{ + Key: "operationId", + Value: slog.StringValue(l.operationId), + }) + } + for attributeKey, attributeValue := range l.attributes { + attrs = append(attrs, slog.Attr{ + Key: attributeKey, + Value: slog.StringValue(attributeValue), + }) + } + return attrs +} + +/* +NewLogger creates a new logger. +By default this logger will output to stdout, in un-structured text format. +If STRUCTURED_LOGGING environment variable is set to "on", output will be written in structured JSON format by deafult. +You can customize the logger by passing LoggerOptionFuction to this function, which will override the default any defaults. +*/ +func NewLogger(optFuncs ...LoggerOptionFuction) *slog.Logger { + loggerOpts := &LoggerOptions{ + output: os.Stdout, + structured: structuredLoggingEnvVar, + logLevel: loggingLevelEnvVar, + attributes: make(map[string]string), + } + for _, optFunc := range optFuncs { + optFunc(loggerOpts) + } + handler := buildHandler(loggerOpts) + return slog.New(handler) +} + +func buildHandler(loggerOptions *LoggerOptions) slog.Handler { + handlerOpts := &slog.HandlerOptions{ + Level: loggerOptions.logLevel, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == "level" { + return slog.Attr{ + Key: "severity", + Value: a.Value, + } + } + if a.Key == "msg" { + return slog.Attr{ + Key: "message", + Value: a.Value, + } + } else if a.Key == "time" { + // Convert time to UTC + return slog.Attr{ + Key: "time", + Value: slog.TimeValue(a.Value.Time().UTC()), + } + } + return a + }, + } + var handler slog.Handler + if loggerOptions.structured { + handler = slog.NewJSONHandler(loggerOptions.output, handlerOpts) + } else { + handler = slog.NewTextHandler(loggerOptions.output, handlerOpts) + } + return handler.WithAttrs(loggerOptions.Attrs()) +}