Merge pull request #2569 from sixcolors/2258-logger-latency

💄 feat(middleware/logger): latency match gin-gonic/gin formatter

middleware/logger/logger_test.go

@@ -205,6 +205,56 @@ func Test_Logger_All(t *testing.T) {
 	utils.AssertEqual(t, expected, buf.String())
 }
 
+// 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()
+	logger := New(Config{
+		Output: buff,
+		Format: "${latency}",
+	})
+	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
+		utils.AssertEqual(t, bytes.HasSuffix(buff.Bytes(), []byte(tu.unit)), true, "Expected latency to be in %s, got %s", tu.unit, buff.String())
+
+		// Reset the buffer
+		buff.Reset()
+	}
+}
+
 // go test -run Test_Query_Params
 func Test_Query_Params(t *testing.T) {
 	t.Parallel()

middleware/logger/tags.go

@@ -192,7 +192,7 @@ func createTagMap(cfg *Config) map[string]LogFunc {
 		},
 		TagLatency: func(output Buffer, c *fiber.Ctx, data *Data, extraParam string) (int, error) {
 			latency := data.Stop.Sub(data.Start)
-			return output.WriteString(fmt.Sprintf("%7v", latency))
+			return output.WriteString(fmt.Sprintf("%13v", latency))
 		},
 		TagTime: func(output Buffer, c *fiber.Ctx, data *Data, extraParam string) (int, error) {
 			return output.WriteString(data.Timestamp.Load().(string)) //nolint:forcetypeassert // We always store a string in here