Skip to content

Commit

Permalink
🐛 fix(middleware/logger): default latency output format (#2580)
Browse files Browse the repository at this point in the history
* fix: default logger formater latency

* test: add Test_Logger_WithLatency_DefaultFormat

* test: rm t.Parallel() from Latency tests

Trying to make windows CI pass....

* test: fix windows sleep issue
  • Loading branch information
sixcolors authored Aug 17, 2023
1 parent 2624c5d commit c3ae066
Show file tree
Hide file tree
Showing 2 changed files with 75 additions and 13 deletions.
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

0 comments on commit c3ae066

Please sign in to comment.