From 0480e066a3f1ae97dbab8fcb6303589eb0fa724c Mon Sep 17 00:00:00 2001 From: tjpcc Date: Mon, 23 Jan 2023 22:15:16 -0700 Subject: logging library up to top level --- contrib/cgi/cgi.go | 7 ++- contrib/log/log.go | 35 -------------- contrib/tlsauth/auth_test.go | 1 + examples/cgi/main.go | 8 ++-- examples/cowsay/main.go | 8 ++-- examples/fileserver/main.go | 9 ++-- examples/inspectls/main.go | 8 ++-- gemini/roundtrip_test.go | 2 +- gemini/serve.go | 7 +++ logging/logger.go | 43 +++++++++++++++++ logging/middleware.go | 107 +++++++++++++++++++++++++++++++++++++++++++ 11 files changed, 186 insertions(+), 49 deletions(-) delete mode 100644 contrib/log/log.go create mode 100644 logging/logger.go create mode 100644 logging/middleware.go diff --git a/contrib/cgi/cgi.go b/contrib/cgi/cgi.go index 6a420b3..ab10622 100644 --- a/contrib/cgi/cgi.go +++ b/contrib/cgi/cgi.go @@ -110,7 +110,12 @@ func RunCGI( } basename := pathSegments[len(pathSegments)-1] - scriptName := req.Path[:len(req.Path)-len(pathInfo)] + infoLen := len(pathInfo) + if pathInfo == "/" { + infoLen -= 1 + } + + scriptName := req.Path[:len(req.Path)-infoLen] if strings.HasSuffix(scriptName, "/") { scriptName = scriptName[:len(scriptName)-1] } diff --git a/contrib/log/log.go b/contrib/log/log.go deleted file mode 100644 index 0060f4e..0000000 --- a/contrib/log/log.go +++ /dev/null @@ -1,35 +0,0 @@ -package log - -import ( - "context" - "io" - "time" - - kitlog "github.com/go-kit/log" - - "tildegit.org/tjp/gus" -) - -func Requests(out io.Writer, logger kitlog.Logger) gus.Middleware { - if logger == nil { - logger = kitlog.NewLogfmtLogger(kitlog.NewSyncWriter(out)) - } - - return func(next gus.Handler) gus.Handler { - return func(ctx context.Context, r *gus.Request) (resp *gus.Response) { - start := time.Now() - defer func() { - end := time.Now() - logger.Log( - "msg", "request", - "ts", end, - "dur", end.Sub(start), - "url", r.URL, - "status", resp.Status, - ) - }() - - return next(ctx, r) - } - } -} diff --git a/contrib/tlsauth/auth_test.go b/contrib/tlsauth/auth_test.go index 8361fc3..41292b4 100644 --- a/contrib/tlsauth/auth_test.go +++ b/contrib/tlsauth/auth_test.go @@ -137,6 +137,7 @@ func setup( server, err := gemini.NewServer( context.Background(), + nil, serverTLS, "tcp", "127.0.0.1:0", diff --git a/examples/cgi/main.go b/examples/cgi/main.go index 3dfec29..6036454 100644 --- a/examples/cgi/main.go +++ b/examples/cgi/main.go @@ -8,8 +8,8 @@ import ( "syscall" "tildegit.org/tjp/gus/contrib/cgi" - guslog "tildegit.org/tjp/gus/contrib/log" "tildegit.org/tjp/gus/gemini" + "tildegit.org/tjp/gus/logging" ) func main() { @@ -25,15 +25,17 @@ func main() { // make use of a CGI request handler cgiHandler := cgi.CGIDirectory("/cgi-bin", "./cgi-bin") + _, infoLog, _, errLog := logging.DefaultLoggers() + // add stdout logging to the request handler - handler := guslog.Requests(os.Stdout, nil)(cgiHandler) + handler := logging.LogRequests(infoLog)(cgiHandler) // set up signals to trigger graceful shutdown ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGHUP) defer stop() // run the server - server, err := gemini.NewServer(ctx, tlsconf, "tcp4", ":1965", handler) + server, err := gemini.NewServer(ctx, errLog, tlsconf, "tcp4", ":1965", handler) if err != nil { log.Fatal(err) } diff --git a/examples/cowsay/main.go b/examples/cowsay/main.go index fc5e89f..b239019 100644 --- a/examples/cowsay/main.go +++ b/examples/cowsay/main.go @@ -9,8 +9,8 @@ import ( "os/exec" "tildegit.org/tjp/gus" - guslog "tildegit.org/tjp/gus/contrib/log" "tildegit.org/tjp/gus/gemini" + "tildegit.org/tjp/gus/logging" ) func main() { @@ -23,11 +23,13 @@ func main() { log.Fatal(err) } + _, infoLog, _, errLog := logging.DefaultLoggers() + // add request logging to the request handler - handler := guslog.Requests(os.Stdout, nil)(cowsayHandler) + handler := logging.LogRequests(infoLog)(cowsayHandler) // run the server - server, err := gemini.NewServer(context.Background(), tlsconf, "tcp4", ":1965", handler) + server, err := gemini.NewServer(context.Background(), errLog, tlsconf, "tcp4", ":1965", handler) if err != nil { log.Fatal(err) } diff --git a/examples/fileserver/main.go b/examples/fileserver/main.go index 35c8708..e70974f 100644 --- a/examples/fileserver/main.go +++ b/examples/fileserver/main.go @@ -7,8 +7,8 @@ import ( "tildegit.org/tjp/gus" "tildegit.org/tjp/gus/contrib/fs" - guslog "tildegit.org/tjp/gus/contrib/log" "tildegit.org/tjp/gus/gemini" + "tildegit.org/tjp/gus/logging" ) func main() { @@ -32,11 +32,14 @@ func main() { // finally, try to find a file at the request path and respond with that fs.FileHandler(fileSystem), ) + + _, infoLog, _, errLog := logging.DefaultLoggers() + // add request logging to stdout - handler = guslog.Requests(os.Stdout, nil)(handler) + handler = logging.LogRequests(infoLog)(handler) // run the server - server, err := gemini.NewServer(context.Background(), tlsconf, "tcp4", ":1965", handler) + server, err := gemini.NewServer(context.Background(), errLog, tlsconf, "tcp4", ":1965", handler) if err != nil { log.Fatal(err) } diff --git a/examples/inspectls/main.go b/examples/inspectls/main.go index 65c5229..5022888 100644 --- a/examples/inspectls/main.go +++ b/examples/inspectls/main.go @@ -13,8 +13,8 @@ import ( "strings" "tildegit.org/tjp/gus" - guslog "tildegit.org/tjp/gus/contrib/log" "tildegit.org/tjp/gus/gemini" + "tildegit.org/tjp/gus/logging" ) func main() { @@ -27,11 +27,13 @@ func main() { log.Fatal(err) } + _, infoLog, _, errLog := logging.DefaultLoggers() + // add stdout logging to the request handler - handler := guslog.Requests(os.Stdout, nil)(inspectHandler) + handler := logging.LogRequests(infoLog)(inspectHandler) // run the server - server, err := gemini.NewServer(context.Background(), tlsconf, "tcp4", ":1965", handler) + server, err := gemini.NewServer(context.Background(), errLog, tlsconf, "tcp4", ":1965", handler) if err != nil { log.Fatal(err) } diff --git a/gemini/roundtrip_test.go b/gemini/roundtrip_test.go index 326ffbc..4bac239 100644 --- a/gemini/roundtrip_test.go +++ b/gemini/roundtrip_test.go @@ -23,7 +23,7 @@ func TestRoundTrip(t *testing.T) { return gemini.Success("text/gemini", bytes.NewBufferString("you've found my page")) } - server, err := gemini.NewServer(context.Background(), tlsConf, "tcp", "127.0.0.1:0", handler) + server, err := gemini.NewServer(context.Background(), nil, tlsConf, "tcp", "127.0.0.1:0", handler) if err != nil { t.Fatalf("NewServer(): %s", err.Error()) } diff --git a/gemini/serve.go b/gemini/serve.go index c148558..cd51370 100644 --- a/gemini/serve.go +++ b/gemini/serve.go @@ -8,10 +8,12 @@ import ( "sync" "tildegit.org/tjp/gus" + "tildegit.org/tjp/gus/logging" ) type server struct { ctx context.Context + errorLog logging.Logger network string address string cancel context.CancelFunc @@ -23,6 +25,7 @@ type server struct { // NewServer builds a gemini server. func NewServer( ctx context.Context, + errorLog logging.Logger, tlsConfig *tls.Config, network string, address string, @@ -37,6 +40,7 @@ func NewServer( s := &server{ ctx: ctx, + errorLog: errorLog, network: addr.Network(), address: addr.String(), wg: &sync.WaitGroup{}, @@ -69,7 +73,10 @@ func (s *server) Serve() error { if err != nil { if s.Closed() { err = nil + } else { + s.errorLog.Log("msg", "accept_error", "error", err) } + return err } diff --git a/logging/logger.go b/logging/logger.go new file mode 100644 index 0000000..f80a1ae --- /dev/null +++ b/logging/logger.go @@ -0,0 +1,43 @@ +package logging + +import ( + "os" + + "github.com/go-kit/log" + "github.com/go-kit/log/level" + "github.com/go-kit/log/term" +) + +// Logger records log lines to an output. +type Logger interface { + Log(keyvals ...any) error +} + +// DefaultLoggers produces helpful base loggers for each level. +// +// They write logfmt to standard out, annotated with ANSI colors depending on the level. +func DefaultLoggers() (debug, info, warn, error Logger) { + base := term.NewLogger(os.Stdout, log.NewLogfmtLogger, func(keyvals ...any) term.FgBgColor { + for i := 0; i < len(keyvals)-1; i += 2 { + if keyvals[i] != "level" { + continue + } + + switch keyvals[i+1] { + case level.DebugValue(): + return term.FgBgColor{Fg: term.DarkGray} + case level.InfoValue(): + return term.FgBgColor{Fg: term.Green} + case level.WarnValue(): + return term.FgBgColor{Fg: term.Yellow} + case level.ErrorValue(): + return term.FgBgColor{Fg: term.Red} + } + } + + return term.FgBgColor{} + }) + base = log.NewSyncLogger(base) + + return level.Debug(base), level.Info(base), level.Warn(base), level.Error(base) +} diff --git a/logging/middleware.go b/logging/middleware.go new file mode 100644 index 0000000..cbb345a --- /dev/null +++ b/logging/middleware.go @@ -0,0 +1,107 @@ +package logging + +import ( + "context" + "errors" + "io" + "time" + + "tildegit.org/tjp/gus" +) + +func LogRequests(logger Logger) gus.Middleware { + return func(inner gus.Handler) gus.Handler { + return func(ctx context.Context, request *gus.Request) *gus.Response { + start := time.Now() + + response := inner(ctx, request) + if response != nil { + body := loggedResponseBody{ + request: request, + response: response, + body: response.Body, + start: start, + logger: logger, + } + response.Body = &body + } + + return response + } + } +} + +type loggedResponseBody struct { + request *gus.Request + response *gus.Response + body io.Reader + + start time.Time + + written int + logger Logger +} + +func loggingBody(logger Logger, request *gus.Request, response *gus.Response) io.Reader { + body := &loggedResponseBody{ + request: request, + response: response, + body: response.Body, + start: time.Now(), + written: 0, + logger: logger, + } + + if _, ok := response.Body.(io.WriterTo); ok { + return loggedWriteToResponseBody{body} + } + + return body +} + +func (lr *loggedResponseBody) log() { + end := time.Now() + _ = lr.logger.Log( + "msg", "request", + "ts", end, + "dur", end.Sub(lr.start), + "url", lr.request.URL, + "status", lr.response.Status, + "bodylen", lr.written, + ) +} + +func (lr *loggedResponseBody) Read(b []byte) (int, error) { + if lr.body == nil { + return 0, io.EOF + } + + wr, err := lr.body.Read(b) + lr.written += wr + + if errors.Is(err, io.EOF) { + lr.log() + } + + return wr, err +} + +func (lr *loggedResponseBody) Close() error { + if cl, ok := lr.body.(io.Closer); ok { + return cl.Close() + } + return nil +} + +type loggedWriteToResponseBody struct { + *loggedResponseBody +} + +func (lwtr loggedWriteToResponseBody) WriteTo(dst io.Writer) (int64, error) { + n, err := lwtr.body.(io.WriterTo).WriteTo(dst) + if err == nil { + lwtr.written += int(n) + lwtr.log() + } + return n, err +} -- cgit v1.2.3