From a594876867f775f2c998f9a4a600375c33627994 Mon Sep 17 00:00:00 2001 From: Eric Promislow Date: Wed, 14 Aug 2024 10:27:19 -0700 Subject: [PATCH 1/5] Keep the logger 'WriterLevel' in sync with the logger's own level. Add a 'DisplayServerLogs' field. When this option is true, all logs from the http.Server are displayed as errors. This makes sense, because the docs for 'http.Server.ErrorLog' says mostly error messages are written to it. Unit tests need to use mutexes so we can have the logger write to a wrapped buffer and safely read from it after writing is finished. --- go.mod | 4 +- server/server.go | 26 ++++++++- server/server_test.go | 131 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 155 insertions(+), 6 deletions(-) create mode 100644 server/server_test.go diff --git a/go.mod b/go.mod index 9a95411..f02d7bf 100644 --- a/go.mod +++ b/go.mod @@ -1,8 +1,6 @@ module github.com/rancher/dynamiclistener -go 1.22.0 - -toolchain go1.22.1 +go 1.23.0 require ( github.com/rancher/wrangler/v3 v3.0.0 diff --git a/server/server.go b/server/server.go index 9ad31b1..001cf9f 100644 --- a/server/server.go +++ b/server/server.go @@ -36,9 +36,32 @@ type ListenOpts struct { BindHost string NoRedirect bool TLSListenerConfig dynamiclistener.Config + + // Override legacy behavior where server logs written to the application's logrus object + // were dropped unless logrus was set to debug-level (such as by launching steve with '--debug'). + // Setting this to true results in server logs appearing at an ERROR level. + DisplayServerLogs bool } func ListenAndServe(ctx context.Context, httpsPort, httpPort int, handler http.Handler, opts *ListenOpts) error { + writer := logrus.StandardLogger().WriterLevel(logrus.DebugLevel) + if opts.DisplayServerLogs { + // Create a new logger the writes to which are at the same level as it's + // configured at, with an "ERROR" prefix (as the server writes "un-levelled" + // text to the log stream it's handled). + // We aren't grabbing `logrus.StandardLogger()` because that gives a reference + // to the one global logger, and we don't want to change its logging level here. + logger := logrus.New() + logger.SetOutput(logrus.StandardLogger().Out) + logger.SetLevel(logrus.ErrorLevel) + writer = logger.WriterLevel(logrus.ErrorLevel) + } + // Otherwise preserve legacy behaviour of displaying server logs only in debug mode. + errorLog := log.New(writer, "", log.LstdFlags) + return listenAndServeWithLogger(ctx, httpsPort, httpPort, handler, opts, errorLog) +} + +func listenAndServeWithLogger(ctx context.Context, httpsPort, httpPort int, handler http.Handler, opts *ListenOpts, errorLog *log.Logger) error { if opts == nil { opts = &ListenOpts{} } @@ -47,9 +70,6 @@ func ListenAndServe(ctx context.Context, httpsPort, httpPort int, handler http.H opts.TLSListenerConfig.TLSConfig = &tls.Config{} } - logger := logrus.StandardLogger() - errorLog := log.New(logger.WriterLevel(logrus.DebugLevel), "", log.LstdFlags) - if httpsPort > 0 { tlsTCPListener, err := dynamiclistener.NewTCPListener(opts.BindHost, httpsPort) if err != nil { diff --git a/server/server_test.go b/server/server_test.go new file mode 100644 index 0000000..0bad096 --- /dev/null +++ b/server/server_test.go @@ -0,0 +1,131 @@ +package server + +import ( + "bytes" + "context" + "fmt" + "log" + "net" + "net/http" + "sync" + "testing" + "time" + + "github.com/sirupsen/logrus" + assertPkg "github.com/stretchr/testify/assert" +) + +type alwaysPanicHandler struct { + msg string +} + +func (z *alwaysPanicHandler) ServeHTTP(_ http.ResponseWriter, _ *http.Request) { + panic(z.msg) +} + +// safeWriter is used to allow writing to a buffer-based log in a web server +// and safely read from it in the client (i.e. this test code) +type safeWriter struct { + writer *bytes.Buffer + mutex *sync.Mutex +} + +func newSafeWriter(writer *bytes.Buffer, mutex *sync.Mutex) *safeWriter { + return &safeWriter{writer: writer, mutex: mutex} +} + +func (s *safeWriter) Write(p []byte) (n int, err error) { + s.mutex.Lock() + defer s.mutex.Unlock() + return s.writer.Write(p) +} + +func TestHttpServerLogWithLogrus(t *testing.T) { + assert := assertPkg.New(t) + message := "debug-level writer" + msg := fmt.Sprintf("panicking context: %s", message) + var buf bytes.Buffer + var mutex sync.Mutex + safeWriter := newSafeWriter(&buf, &mutex) + doRequest(t, safeWriter, message, logrus.ErrorLevel) + + mutex.Lock() + s := buf.String() + assert.Greater(len(s), 0) + assert.Contains(s, msg) + assert.Contains(s, "panic serving 127.0.0.1") + mutex.Unlock() +} + +func TestHttpNoServerLogsWithLogrus(t *testing.T) { + assert := assertPkg.New(t) + + message := "error-level writer" + var buf bytes.Buffer + var mutex sync.Mutex + safeWriter := newSafeWriter(&buf, &mutex) + doRequest(t, safeWriter, message, logrus.DebugLevel) + + mutex.Lock() + s := buf.String() + if len(s) > 0 { + assert.NotContains(s, message) + } + mutex.Unlock() +} + +func doRequest(t *testing.T, safeWriter *safeWriter, message string, logLevel logrus.Level) { + assert := assertPkg.New(t) + ctx, cancel := context.WithCancel(context.Background()) + httpPort := 9012 + httpsPort := 0 + msg := fmt.Sprintf("panicking context: %s", message) + handler := alwaysPanicHandler{msg: msg} + listenOpts := &ListenOpts{ + BindHost: "127.0.0.1", + } + + logger := logrus.StandardLogger() + logger.SetOutput(safeWriter) + logger.SetLevel(logrus.ErrorLevel) + writer := logger.WriterLevel(logLevel) + errorLog := log.New(writer, "", log.LstdFlags) + + err := listenAndServeWithLogger(ctx, httpsPort, httpPort, &handler, listenOpts, errorLog) + assert.Nil(err) + + makeTheHttpRequest(assert, httpPort) + cancel() +} + +func makeTheHttpRequest(assert *assertPkg.Assertions, port int) { + addr := fmt.Sprintf("127.0.0.1:%d", port) + url := fmt.Sprintf("%s://%s/", "http", addr) + + waitTime := 10 * time.Millisecond + for { + conn, err := net.Dial("tcp", addr) + if err == nil { + conn.Close() + break + } + fmt.Println("Waiting for server to be ready...") + time.Sleep(waitTime) + waitTime += 10 * time.Millisecond + } + + client := &http.Client{ + Timeout: 30 * time.Second, + } + req, err := http.NewRequest("GET", url, nil) + if err != nil { + fmt.Println("Error creating request:", err) + return + } + resp, err := client.Do(req) + assert.Error(err, "server should have panicked on request") + if resp != nil { + defer resp.Body.Close() + fmt.Println("Response status:", resp.Status) + } +} From 6b9fa231efa0915263c66ec2cefba3c352311d4e Mon Sep 17 00:00:00 2001 From: Eric Promislow Date: Wed, 28 Aug 2024 13:45:11 -0700 Subject: [PATCH 2/5] Do all the testing in the top-level Test* functions. --- go.mod | 4 +++- server/server_test.go | 42 +++++++++++++++++++++++++----------------- 2 files changed, 28 insertions(+), 18 deletions(-) diff --git a/go.mod b/go.mod index f02d7bf..9a95411 100644 --- a/go.mod +++ b/go.mod @@ -1,6 +1,8 @@ module github.com/rancher/dynamiclistener -go 1.23.0 +go 1.22.0 + +toolchain go1.22.1 require ( github.com/rancher/wrangler/v3 v3.0.0 diff --git a/server/server_test.go b/server/server_test.go index 0bad096..915ecb2 100644 --- a/server/server_test.go +++ b/server/server_test.go @@ -47,7 +47,8 @@ func TestHttpServerLogWithLogrus(t *testing.T) { var buf bytes.Buffer var mutex sync.Mutex safeWriter := newSafeWriter(&buf, &mutex) - doRequest(t, safeWriter, message, logrus.ErrorLevel) + err := doRequest(safeWriter, message, logrus.ErrorLevel) + assert.Nil(err) mutex.Lock() s := buf.String() @@ -64,7 +65,8 @@ func TestHttpNoServerLogsWithLogrus(t *testing.T) { var buf bytes.Buffer var mutex sync.Mutex safeWriter := newSafeWriter(&buf, &mutex) - doRequest(t, safeWriter, message, logrus.DebugLevel) + err := doRequest(safeWriter, message, logrus.DebugLevel) + assert.Nil(err) mutex.Lock() s := buf.String() @@ -74,15 +76,16 @@ func TestHttpNoServerLogsWithLogrus(t *testing.T) { mutex.Unlock() } -func doRequest(t *testing.T, safeWriter *safeWriter, message string, logLevel logrus.Level) { - assert := assertPkg.New(t) +func doRequest(safeWriter *safeWriter, message string, logLevel logrus.Level) error { ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + host := "127.0.0.1" httpPort := 9012 httpsPort := 0 msg := fmt.Sprintf("panicking context: %s", message) handler := alwaysPanicHandler{msg: msg} listenOpts := &ListenOpts{ - BindHost: "127.0.0.1", + BindHost: host, } logger := logrus.StandardLogger() @@ -91,26 +94,30 @@ func doRequest(t *testing.T, safeWriter *safeWriter, message string, logLevel lo writer := logger.WriterLevel(logLevel) errorLog := log.New(writer, "", log.LstdFlags) - err := listenAndServeWithLogger(ctx, httpsPort, httpPort, &handler, listenOpts, errorLog) - assert.Nil(err) - - makeTheHttpRequest(assert, httpPort) - cancel() + if err := listenAndServeWithLogger(ctx, httpsPort, httpPort, &handler, listenOpts, errorLog); err != nil { + return err + } + addr := fmt.Sprintf("%s:%d", host, httpPort) + return makeTheHttpRequest(addr) } -func makeTheHttpRequest(assert *assertPkg.Assertions, port int) { - addr := fmt.Sprintf("127.0.0.1:%d", port) +func makeTheHttpRequest(addr string) error { url := fmt.Sprintf("%s://%s/", "http", addr) waitTime := 10 * time.Millisecond + totalTime := 0 * time.Millisecond + const maxWaitTime = 10 * time.Second + // Waiting for server to be ready..., max of maxWaitTime for { conn, err := net.Dial("tcp", addr) if err == nil { conn.Close() break + } else if totalTime > maxWaitTime { + return fmt.Errorf("timed out waiting for the server to start after %d msec", totalTime/1e6) } - fmt.Println("Waiting for server to be ready...") time.Sleep(waitTime) + totalTime += waitTime waitTime += 10 * time.Millisecond } @@ -119,13 +126,14 @@ func makeTheHttpRequest(assert *assertPkg.Assertions, port int) { } req, err := http.NewRequest("GET", url, nil) if err != nil { - fmt.Println("Error creating request:", err) - return + return fmt.Errorf("error creating request: %w", err) } resp, err := client.Do(req) - assert.Error(err, "server should have panicked on request") + if err == nil { + return fmt.Errorf("server should have panicked on request") + } if resp != nil { defer resp.Body.Close() - fmt.Println("Response status:", resp.Status) } + return nil } From 678e190743c168d106f439c60318d6fabc57ba2d Mon Sep 17 00:00:00 2001 From: Eric Promislow Date: Wed, 28 Aug 2024 14:16:43 -0700 Subject: [PATCH 3/5] Just change the level and output-handler on the logrus's underlying logger. --- server/server.go | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/server/server.go b/server/server.go index 001cf9f..7af26cd 100644 --- a/server/server.go +++ b/server/server.go @@ -44,16 +44,9 @@ type ListenOpts struct { } func ListenAndServe(ctx context.Context, httpsPort, httpPort int, handler http.Handler, opts *ListenOpts) error { - writer := logrus.StandardLogger().WriterLevel(logrus.DebugLevel) + logger := logrus.StandardLogger() + writer := logger.WriterLevel(logrus.DebugLevel) if opts.DisplayServerLogs { - // Create a new logger the writes to which are at the same level as it's - // configured at, with an "ERROR" prefix (as the server writes "un-levelled" - // text to the log stream it's handled). - // We aren't grabbing `logrus.StandardLogger()` because that gives a reference - // to the one global logger, and we don't want to change its logging level here. - logger := logrus.New() - logger.SetOutput(logrus.StandardLogger().Out) - logger.SetLevel(logrus.ErrorLevel) writer = logger.WriterLevel(logrus.ErrorLevel) } // Otherwise preserve legacy behaviour of displaying server logs only in debug mode. From d1fbc00b82291af32a26b9e4b6a16d424c2243f5 Mon Sep 17 00:00:00 2001 From: Eric Promislow Date: Thu, 29 Aug 2024 12:44:36 -0700 Subject: [PATCH 4/5] Stop using and testing the intermediate function. Directly test the exported ListenAndServe function. --- server/server.go | 16 +++++++--------- server/server_test.go | 11 +++-------- 2 files changed, 10 insertions(+), 17 deletions(-) diff --git a/server/server.go b/server/server.go index 7af26cd..76e88ee 100644 --- a/server/server.go +++ b/server/server.go @@ -5,6 +5,7 @@ import ( "crypto" "crypto/tls" "crypto/x509" + "errors" "fmt" "log" "net" @@ -46,18 +47,15 @@ type ListenOpts struct { func ListenAndServe(ctx context.Context, httpsPort, httpPort int, handler http.Handler, opts *ListenOpts) error { logger := logrus.StandardLogger() writer := logger.WriterLevel(logrus.DebugLevel) + if opts == nil { + opts = &ListenOpts{} + } if opts.DisplayServerLogs { writer = logger.WriterLevel(logrus.ErrorLevel) } // Otherwise preserve legacy behaviour of displaying server logs only in debug mode. - errorLog := log.New(writer, "", log.LstdFlags) - return listenAndServeWithLogger(ctx, httpsPort, httpPort, handler, opts, errorLog) -} -func listenAndServeWithLogger(ctx context.Context, httpsPort, httpPort int, handler http.Handler, opts *ListenOpts, errorLog *log.Logger) error { - if opts == nil { - opts = &ListenOpts{} - } + errorLog := log.New(writer, "", log.LstdFlags) if opts.TLSListenerConfig.TLSConfig == nil { opts.TLSListenerConfig.TLSConfig = &tls.Config{} @@ -89,7 +87,7 @@ func listenAndServeWithLogger(ctx context.Context, httpsPort, httpPort int, hand go func() { logrus.Infof("Listening on %s:%d", opts.BindHost, httpsPort) err := tlsServer.Serve(tlsTCPListener) - if err != http.ErrServerClosed && err != nil { + if !errors.Is(err, http.ErrServerClosed) && err != nil { logrus.Fatalf("https server failed: %v", err) } }() @@ -111,7 +109,7 @@ func listenAndServeWithLogger(ctx context.Context, httpsPort, httpPort int, hand go func() { logrus.Infof("Listening on %s:%d", opts.BindHost, httpPort) err := httpServer.ListenAndServe() - if err != http.ErrServerClosed && err != nil { + if !errors.Is(err, http.ErrServerClosed) && err != nil { logrus.Fatalf("http server failed: %v", err) } }() diff --git a/server/server_test.go b/server/server_test.go index 915ecb2..28a17b1 100644 --- a/server/server_test.go +++ b/server/server_test.go @@ -4,7 +4,6 @@ import ( "bytes" "context" "fmt" - "log" "net" "net/http" "sync" @@ -86,15 +85,11 @@ func doRequest(safeWriter *safeWriter, message string, logLevel logrus.Level) er handler := alwaysPanicHandler{msg: msg} listenOpts := &ListenOpts{ BindHost: host, + DisplayServerLogs: logLevel == logrus.ErrorLevel, } - logger := logrus.StandardLogger() - logger.SetOutput(safeWriter) - logger.SetLevel(logrus.ErrorLevel) - writer := logger.WriterLevel(logLevel) - errorLog := log.New(writer, "", log.LstdFlags) - - if err := listenAndServeWithLogger(ctx, httpsPort, httpPort, &handler, listenOpts, errorLog); err != nil { + logrus.StandardLogger().SetOutput(safeWriter) + if err := ListenAndServe(ctx, httpsPort, httpPort, &handler, listenOpts); err != nil { return err } addr := fmt.Sprintf("%s:%d", host, httpPort) From 43f79036b0d706c1ceaffec70773a0716725f58a Mon Sep 17 00:00:00 2001 From: Eric Promislow Date: Thu, 29 Aug 2024 13:54:12 -0700 Subject: [PATCH 5/5] Revert change using `!errors.Is(...)` vs `err != ...` --- server/server.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/server/server.go b/server/server.go index 76e88ee..787ad05 100644 --- a/server/server.go +++ b/server/server.go @@ -5,7 +5,6 @@ import ( "crypto" "crypto/tls" "crypto/x509" - "errors" "fmt" "log" "net" @@ -87,7 +86,7 @@ func ListenAndServe(ctx context.Context, httpsPort, httpPort int, handler http.H go func() { logrus.Infof("Listening on %s:%d", opts.BindHost, httpsPort) err := tlsServer.Serve(tlsTCPListener) - if !errors.Is(err, http.ErrServerClosed) && err != nil { + if err != http.ErrServerClosed && err != nil { logrus.Fatalf("https server failed: %v", err) } }() @@ -109,7 +108,7 @@ func ListenAndServe(ctx context.Context, httpsPort, httpPort int, handler http.H go func() { logrus.Infof("Listening on %s:%d", opts.BindHost, httpPort) err := httpServer.ListenAndServe() - if !errors.Is(err, http.ErrServerClosed) && err != nil { + if err != http.ErrServerClosed && err != nil { logrus.Fatalf("http server failed: %v", err) } }()