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(), diff --git a/middleware/logger/logger_test.go b/middleware/logger/logger_test.go index a5764580f9..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,6 +206,31 @@ 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() @@ -218,15 +244,48 @@ 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 + + // 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 + 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 := getLatencyTimeUnits() // Initialize a new time unit sleepDuration := 1 * time.Nanosecond @@ -248,7 +307,10 @@ 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()) + // 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()