Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

🐛 fix(middleware/logger): default latency output format #2580

Merged
merged 4 commits into from
Aug 17, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions middleware/logger/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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(),
Expand All @@ -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(),
Expand Down
80 changes: 71 additions & 9 deletions middleware/logger/logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ import (
"net/http"
"net/http/httptest"
"os"
"runtime"
"sync"
"testing"
"time"
Expand Down Expand Up @@ -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()
Expand All @@ -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
Expand All @@ -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()
Expand Down
Loading