From f97d278f9961859078ac5ed95cd81eeac884ad3b Mon Sep 17 00:00:00 2001 From: Jason McNeil Date: Wed, 16 Aug 2023 11:46:20 -0300 Subject: [PATCH 1/4] fix: default logger formater latency --- middleware/logger/logger.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/middleware/logger/logger.go b/middleware/logger/logger.go index ec4aa3cafc..f33f3562a3 100644 --- a/middleware/logger/logger.go +++ b/middleware/logger/logger.go @@ -146,10 +146,10 @@ func New(config ...Config) fiber.Handler { formatErr = colors.Red + " | " + chainErr.Error() + colors.Reset } _, _ = buf.WriteString( //nolint:errcheck // This will never fail - fmt.Sprintf("%s |%s %3d %s| %7v | %15s |%s %-7s %s| %-"+errPaddingStr+"s %s\n", + fmt.Sprintf("%s |%s %3d %s| %13v | %15s |%s %-7s %s| %-"+errPaddingStr+"s %s\n", timestamp.Load().(string), statusColor(c.Response().StatusCode(), colors), c.Response().StatusCode(), colors.Reset, - data.Stop.Sub(data.Start).Round(time.Millisecond), + data.Stop.Sub(data.Start), c.IP(), methodColor(c.Method(), colors), c.Method(), colors.Reset, c.Path(), @@ -161,10 +161,10 @@ func New(config ...Config) fiber.Handler { formatErr = " | " + chainErr.Error() } _, _ = buf.WriteString( //nolint:errcheck // This will never fail - fmt.Sprintf("%s | %3d | %7v | %15s | %-7s | %-"+errPaddingStr+"s %s\n", + fmt.Sprintf("%s | %3d | %13v | %15s | %-7s | %-"+errPaddingStr+"s %s\n", timestamp.Load().(string), c.Response().StatusCode(), - data.Stop.Sub(data.Start).Round(time.Millisecond), + data.Stop.Sub(data.Start), c.IP(), c.Method(), c.Path(), From 6a706305a474592936eb3bf1981452f527b3f0e2 Mon Sep 17 00:00:00 2001 From: Jason McNeil Date: Wed, 16 Aug 2023 12:01:39 -0300 Subject: [PATCH 2/4] test: add Test_Logger_WithLatency_DefaultFormat --- middleware/logger/logger_test.go | 54 +++++++++++++++++++++++++++++++- 1 file changed, 53 insertions(+), 1 deletion(-) diff --git a/middleware/logger/logger_test.go b/middleware/logger/logger_test.go index a5764580f9..746eff0c71 100644 --- a/middleware/logger/logger_test.go +++ b/middleware/logger/logger_test.go @@ -248,7 +248,59 @@ func Test_Logger_WithLatency(t *testing.T) { utils.AssertEqual(t, fiber.StatusOK, resp.StatusCode) // Assert that the log output contains the expected latency value in the current time unit - utils.AssertEqual(t, bytes.HasSuffix(buff.Bytes(), []byte(tu.unit)), true, "Expected latency to be in %s, got %s", tu.unit, buff.String()) + utils.AssertEqual(t, bytes.HasSuffix(buff.Bytes(), []byte(tu.unit)), true, fmt.Sprintf("Expected latency to be in %s, got %s", tu.unit, buff.String())) + + // Reset the buffer + buff.Reset() + } +} + +// go test -run Test_Logger_WithLatency_DefaultFormat +func Test_Logger_WithLatency_DefaultFormat(t *testing.T) { + t.Parallel() + buff := bytebufferpool.Get() + defer bytebufferpool.Put(buff) + app := fiber.New() + logger := New(Config{ + Output: buff, + }) + app.Use(logger) + + // Define a list of time units to test + timeUnits := []struct { + unit string + div time.Duration + }{ + // {"ns", time.Nanosecond}, // TODO: Nano seconds are too fast to test + {"µs", time.Microsecond}, + {"ms", time.Millisecond}, + {"s", time.Second}, + } + + // Initialize a new time unit + sleepDuration := 1 * time.Nanosecond + + // Define a test route that sleeps + app.Get("/test", func(c *fiber.Ctx) error { + time.Sleep(sleepDuration) + return c.SendStatus(fiber.StatusOK) + }) + + // Loop through each time unit and assert that the log output contains the expected latency value + for _, tu := range timeUnits { + // Update the sleep duration for the next iteration + sleepDuration = 1 * tu.div + + // Create a new HTTP request to the test route + resp, err := app.Test(httptest.NewRequest(fiber.MethodGet, "/test", nil), int(2*time.Second)) + utils.AssertEqual(t, nil, err) + utils.AssertEqual(t, fiber.StatusOK, resp.StatusCode) + + // Assert that the log output contains the expected latency value in the current time unit + // parse out the latency value from the log output + latency := bytes.Split(buff.Bytes(), []byte(" | "))[2] + // Assert that the latency value is in the current time unit + utils.AssertEqual(t, bytes.HasSuffix(latency, []byte(tu.unit)), true, fmt.Sprintf("Expected latency to be in %s, got %s", tu.unit, latency)) // Reset the buffer buff.Reset() From c5438351dfa287b3c94a9d4e19d1cb0fe26ddc4b Mon Sep 17 00:00:00 2001 From: Jason McNeil Date: Wed, 16 Aug 2023 21:04:45 -0300 Subject: [PATCH 3/4] test: rm t.Parallel() from Latency tests Trying to make windows CI pass.... --- middleware/logger/logger_test.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/middleware/logger/logger_test.go b/middleware/logger/logger_test.go index 746eff0c71..878ffba6a5 100644 --- a/middleware/logger/logger_test.go +++ b/middleware/logger/logger_test.go @@ -207,7 +207,6 @@ func Test_Logger_All(t *testing.T) { // go test -run Test_Logger_WithLatency func Test_Logger_WithLatency(t *testing.T) { - t.Parallel() buff := bytebufferpool.Get() defer bytebufferpool.Put(buff) app := fiber.New() @@ -257,7 +256,6 @@ func Test_Logger_WithLatency(t *testing.T) { // go test -run Test_Logger_WithLatency_DefaultFormat func Test_Logger_WithLatency_DefaultFormat(t *testing.T) { - t.Parallel() buff := bytebufferpool.Get() defer bytebufferpool.Put(buff) app := fiber.New() From 526653dc5c313666cb5614daaca458ca167380f8 Mon Sep 17 00:00:00 2001 From: Jason McNeil Date: Wed, 16 Aug 2023 21:20:02 -0300 Subject: [PATCH 4/4] test: fix windows sleep issue --- middleware/logger/logger_test.go | 48 ++++++++++++++++++++------------ 1 file changed, 30 insertions(+), 18 deletions(-) diff --git a/middleware/logger/logger_test.go b/middleware/logger/logger_test.go index 878ffba6a5..d563a5ccc6 100644 --- a/middleware/logger/logger_test.go +++ b/middleware/logger/logger_test.go @@ -10,6 +10,7 @@ import ( "net/http" "net/http/httptest" "os" + "runtime" "sync" "testing" "time" @@ -205,8 +206,34 @@ func Test_Logger_All(t *testing.T) { utils.AssertEqual(t, expected, buf.String()) } +func getLatencyTimeUnits() []struct { + unit string + div time.Duration +} { + // windows does not support µs sleep precision + // https://github.com/golang/go/issues/29485 + if runtime.GOOS == "windows" { + return []struct { + unit string + div time.Duration + }{ + {"ms", time.Millisecond}, + {"s", time.Second}, + } + } + return []struct { + unit string + div time.Duration + }{ + {"µs", time.Microsecond}, + {"ms", time.Millisecond}, + {"s", time.Second}, + } +} + // go test -run Test_Logger_WithLatency func Test_Logger_WithLatency(t *testing.T) { + t.Parallel() buff := bytebufferpool.Get() defer bytebufferpool.Put(buff) app := fiber.New() @@ -217,15 +244,7 @@ func Test_Logger_WithLatency(t *testing.T) { app.Use(logger) // Define a list of time units to test - timeUnits := []struct { - unit string - div time.Duration - }{ - // {"ns", time.Nanosecond}, // TODO: Nano seconds are too fast to test - {"µs", time.Microsecond}, - {"ms", time.Millisecond}, - {"s", time.Second}, - } + timeUnits := getLatencyTimeUnits() // Initialize a new time unit sleepDuration := 1 * time.Nanosecond @@ -256,6 +275,7 @@ func Test_Logger_WithLatency(t *testing.T) { // go test -run Test_Logger_WithLatency_DefaultFormat func Test_Logger_WithLatency_DefaultFormat(t *testing.T) { + t.Parallel() buff := bytebufferpool.Get() defer bytebufferpool.Put(buff) app := fiber.New() @@ -265,15 +285,7 @@ func Test_Logger_WithLatency_DefaultFormat(t *testing.T) { app.Use(logger) // Define a list of time units to test - timeUnits := []struct { - unit string - div time.Duration - }{ - // {"ns", time.Nanosecond}, // TODO: Nano seconds are too fast to test - {"µs", time.Microsecond}, - {"ms", time.Millisecond}, - {"s", time.Second}, - } + timeUnits := getLatencyTimeUnits() // Initialize a new time unit sleepDuration := 1 * time.Nanosecond