diff --git a/internal/storage/memory/memory.go b/internal/storage/memory/memory.go index 1e93231a7ca..63b39caf328 100644 --- a/internal/storage/memory/memory.go +++ b/internal/storage/memory/memory.go @@ -20,6 +20,7 @@ type Storage struct { done chan struct{} gcInterval time.Duration mux sync.RWMutex + closeOnce sync.Once } // Entry represents a value stored in memory along with its expiration. @@ -38,7 +39,7 @@ func New(config ...Config) *Storage { store := &Storage{ db: make(map[string]Entry), gcInterval: cfg.GCInterval, - done: make(chan struct{}), + done: make(chan struct{}, 1), } // Start garbage collector @@ -150,7 +151,12 @@ func (s *Storage) ResetWithContext(ctx context.Context) error { // Close stops the background garbage collector and releases resources // associated with the storage instance. func (s *Storage) Close() error { - s.done <- struct{}{} + s.closeOnce.Do(func() { + select { + case s.done <- struct{}{}: + default: + } + }) return nil } diff --git a/internal/storage/memory/memory_test.go b/internal/storage/memory/memory_test.go index 7636d622be4..912f54f9907 100644 --- a/internal/storage/memory/memory_test.go +++ b/internal/storage/memory/memory_test.go @@ -299,6 +299,25 @@ func Test_Storage_Memory_Close(t *testing.T) { require.NoError(t, testStore.Close()) } +func Test_Storage_Memory_Close_Idempotent(t *testing.T) { + t.Parallel() + + testStore := New() + require.NoError(t, testStore.Close()) + + errCh := make(chan error, 1) + go func() { + errCh <- testStore.Close() + }() + + select { + case err := <-errCh: + require.NoError(t, err) + case <-time.After(time.Second): + t.Fatal("second Close blocked") + } +} + func Test_Storage_Memory_Conn(t *testing.T) { t.Parallel() testStore := New() diff --git a/middleware/cache/cache.go b/middleware/cache/cache.go index 50795cb8ac5..5044286d8ec 100644 --- a/middleware/cache/cache.go +++ b/middleware/cache/cache.go @@ -14,7 +14,6 @@ import ( "sort" "strings" "sync" - "sync/atomic" "time" "github.com/gofiber/utils/v2" @@ -24,11 +23,6 @@ import ( "github.com/gofiber/fiber/v3" ) -// timestampUpdatePeriod is the period which is used to check the cache expiration. -// It should not be too long to provide more or less acceptable expiration error, and in the same -// time it should not be too short to avoid overwhelming of the system -const timestampUpdatePeriod = 300 * time.Millisecond - // buffer size for hexpool const ( hexLen = sha256.Size * 2 @@ -148,11 +142,10 @@ func New(config ...Config) fiber.Handler { } } - var ( - // Cache settings - mux = &sync.RWMutex{} - timestamp = safeUnixSeconds(time.Now()) - ) + utils.StartTimeStampUpdater() + + // Cache settings + mux := &sync.RWMutex{} // Create manager to simplify storage operations ( see manager.go ) manager := newManager(cfg.Storage, redactKeys) // Create indexed heap for tracking expirations ( see heap.go ) @@ -169,15 +162,6 @@ func New(config ...Config) fiber.Handler { hashAuthorization := makeHashAuthFunc(hexBufPool) buildVaryKey := makeBuildVaryKeyFunc(hexBufPool) - // Update timestamp in the configured interval - go func() { - ticker := time.NewTicker(timestampUpdatePeriod) - defer ticker.Stop() - for range ticker.C { - atomic.StoreUint64(×tamp, safeUnixSeconds(time.Now())) - } - }() - // Delete key from both manager and storage deleteKey := func(ctx context.Context, dkey string) error { if err := manager.del(ctx, dkey); err != nil { @@ -309,6 +293,12 @@ func New(config ...Config) fiber.Handler { } } + // Get timestamp before locking to keep the critical section small. + ts := uint64(utils.Timestamp()) + if needsExactTimestamp(e, reqDirectives, ts) { + ts = safeUnixSeconds(time.Now()) + } + // Lock entry mux.Lock() locked := true @@ -324,9 +314,6 @@ func New(config ...Config) fiber.Handler { locked = true } } - // Get timestamp - ts := atomic.LoadUint64(×tamp) - // Cache Entry found if e != nil { entryAge = cachedResponseAge(e, ts) @@ -815,7 +802,7 @@ func New(config ...Config) fiber.Handler { return nil } - ts = atomic.LoadUint64(×tamp) + ts = safeUnixSeconds(time.Now()) responseTS := max(ts, nowUnix) maxAgeSeconds := uint64(time.Duration(math.MaxInt64) / time.Second) @@ -1168,6 +1155,34 @@ func parseRequestCacheControlString(cc string) requestCacheDirectives { return parseRequestCacheControl(utils.UnsafeBytes(cc)) } +func needsExactTimestamp(e *item, directives requestCacheDirectives, ts uint64) bool { + if e == nil { + return false + } + + if directives.maxAgeSet || directives.minFreshSet { + return true + } + + if e.exp != 0 { + // utils.Timestamp() is refreshed on a 1s ticker, so it can lag the real + // wall clock by almost one second. Re-read precisely once the cached + // second is within 1s of expiring. + if ts+1 >= e.exp { + return true + } + } + + return timestampPredatesStoredSecond(e, ts) +} + +func timestampPredatesStoredSecond(e *item, ts uint64) bool { + // When the coarse timestamp falls behind the second used to compute this + // entry's exp value, resident age math can underflow. Re-read precisely + // until the shared timestamp has caught up to the stored second. + return e.ttl != 0 && ts < e.exp && e.ttl < e.exp-ts +} + func cachedResponseAge(e *item, now uint64) uint64 { clampedDate := clampDateSeconds(e.date, now) diff --git a/middleware/cache/cache_test.go b/middleware/cache/cache_test.go index b641acc8df0..c20c3b2f7a2 100644 --- a/middleware/cache/cache_test.go +++ b/middleware/cache/cache_test.go @@ -4373,6 +4373,43 @@ func Test_Cache_HelperFunctions(t *testing.T) { require.Equal(t, uint64(1234567890), result) }) + t.Run("needsExactTimestamp nil entry", func(t *testing.T) { + t.Parallel() + require.False(t, needsExactTimestamp(nil, requestCacheDirectives{}, 100)) + }) + + t.Run("needsExactTimestamp request directives", func(t *testing.T) { + t.Parallel() + e := &item{exp: 200} + require.True(t, needsExactTimestamp(e, requestCacheDirectives{maxAgeSet: true}, 100)) + require.True(t, needsExactTimestamp(e, requestCacheDirectives{minFreshSet: true}, 100)) + }) + + t.Run("needsExactTimestamp expiration boundary", func(t *testing.T) { + t.Parallel() + e := &item{exp: 100} + require.True(t, needsExactTimestamp(e, requestCacheDirectives{}, 99)) + require.False(t, needsExactTimestamp(e, requestCacheDirectives{}, 98)) + }) + + t.Run("needsExactTimestamp predates stored second", func(t *testing.T) { + t.Parallel() + e := &item{exp: 110, ttl: 10} + require.True(t, needsExactTimestamp(e, requestCacheDirectives{}, 99)) + }) + + t.Run("timestampPredatesStoredSecond zero ttl", func(t *testing.T) { + t.Parallel() + require.False(t, timestampPredatesStoredSecond(&item{exp: 110}, 99)) + }) + + t.Run("timestampPredatesStoredSecond lagging coarse timestamp", func(t *testing.T) { + t.Parallel() + e := &item{exp: 110, ttl: 10} + require.True(t, timestampPredatesStoredSecond(e, 99)) + require.False(t, timestampPredatesStoredSecond(e, 100)) + }) + t.Run("remainingFreshness nil", func(t *testing.T) { t.Parallel() result := remainingFreshness(nil, 100) diff --git a/middleware/logger/data.go b/middleware/logger/data.go index ce5d2df7ab1..fc5cc3f6e86 100644 --- a/middleware/logger/data.go +++ b/middleware/logger/data.go @@ -1,7 +1,6 @@ package logger import ( - "sync/atomic" "time" ) @@ -13,7 +12,7 @@ type Data struct { Start time.Time Stop time.Time ChainErr error - Timestamp atomic.Value + Timestamp string Pid string ErrPaddingStr string TemplateChain [][]byte diff --git a/middleware/logger/default_logger.go b/middleware/logger/default_logger.go index 528918c4be7..4e3882b217b 100644 --- a/middleware/logger/default_logger.go +++ b/middleware/logger/default_logger.go @@ -45,7 +45,7 @@ func defaultLoggerInstance(c fiber.Ctx, data *Data, cfg *Config) error { fmt.Fprintf( buf, "%s |%s %3d %s| %13v | %15s |%s %-7s %s| %-"+data.ErrPaddingStr+"s %s\n", - data.Timestamp.Load().(string), //nolint:forcetypeassert,errcheck // Timestamp is always a string + data.Timestamp, statusColor(c.Response().StatusCode(), &colors), c.Response().StatusCode(), colors.Reset, data.Stop.Sub(data.Start), c.IP(), @@ -74,7 +74,7 @@ func defaultLoggerInstance(c fiber.Ctx, data *Data, cfg *Config) error { } // Timestamp - buf.WriteString(data.Timestamp.Load().(string)) //nolint:forcetypeassert,errcheck // Timestamp is always a string + buf.WriteString(data.Timestamp) buf.WriteString(" | ") // Status Code with 3 fixed width, right aligned diff --git a/middleware/logger/logger.go b/middleware/logger/logger.go index f7d96211c7e..479b2ebe605 100644 --- a/middleware/logger/logger.go +++ b/middleware/logger/logger.go @@ -12,6 +12,14 @@ import ( "github.com/gofiber/fiber/v3/internal/logtemplate" ) +func loadTimestamp(value *atomic.Value) string { + if timestamp, ok := value.Load().(string); ok { + return timestamp + } + + return "" +} + // defaultErrPadding is the initial column width used by the default access-log // formatter to align the request path against the optional error suffix. The // width grows on first request to fit the longest registered route, but a @@ -34,18 +42,10 @@ func New(config ...Config) fiber.Handler { // Check if format contains latency cfg.isLatencyEnabled = strings.Contains(cfg.Format, "${"+TagLatency+"}") - var timestamp atomic.Value - // Create correct timeformat - timestamp.Store(time.Now().In(cfg.timeZoneLocation).Format(cfg.TimeFormat)) - - // Update date/time every 500 milliseconds in a separate go routine - if strings.Contains(cfg.Format, "${"+TagTime+"}") { - go func() { - for { - time.Sleep(cfg.TimeInterval) - timestamp.Store(time.Now().In(cfg.timeZoneLocation).Format(cfg.TimeFormat)) - } - }() + timeEnabled := strings.Contains(cfg.Format, "${"+TagTime+"}") + var timestamp *atomic.Value + if timeEnabled { + timestamp = sharedTimestamp(cfg.TimeFormat, cfg.timeZoneLocation, cfg.TimeInterval) } // Set PID once pid := strconv.Itoa(os.Getpid()) @@ -106,7 +106,11 @@ func New(config ...Config) fiber.Handler { // no need for a reset, as long as we always override everything data.Pid = pid data.ErrPaddingStr = errPaddingStr - data.Timestamp = timestamp + if timeEnabled { + data.Timestamp = loadTimestamp(timestamp) + } else { + data.Timestamp = "" + } // These compiled chains are shared across requests. The default logger and // custom LoggerFunc implementations must only read them, for example via // logtemplate.ExecuteChains. diff --git a/middleware/logger/logger_test.go b/middleware/logger/logger_test.go index f2f0cf0ec0e..f41aa38e3a4 100644 --- a/middleware/logger/logger_test.go +++ b/middleware/logger/logger_test.go @@ -908,6 +908,54 @@ func Test_Logger_Data_Race(t *testing.T) { require.Equal(t, fiber.StatusOK, resp2.StatusCode) } +func Test_Logger_TimeUpdatesAfterInterval(t *testing.T) { + t.Parallel() + + var buf bytes.Buffer + + app := fiber.New() + app.Use(New(Config{ + Format: "${time}", + TimeFormat: time.RFC3339Nano, + TimeInterval: 10 * time.Millisecond, + Stream: &buf, + })) + app.Get("/", func(c fiber.Ctx) error { + return c.SendStatus(fiber.StatusNoContent) + }) + + resp, err := app.Test(httptest.NewRequest(fiber.MethodGet, "/", http.NoBody)) + require.NoError(t, err) + require.Equal(t, fiber.StatusNoContent, resp.StatusCode) + first := buf.String() + require.NotEmpty(t, first) + + var second string + require.Eventually(t, func() bool { + buf.Reset() + + resp, err = app.Test(httptest.NewRequest(fiber.MethodGet, "/", http.NoBody)) + require.NoError(t, err) + require.Equal(t, fiber.StatusNoContent, resp.StatusCode) + + second = buf.String() + return second != "" && second != first + }, 200*time.Millisecond, 5*time.Millisecond) +} + +func Test_Logger_SharedTimestampState(t *testing.T) { + t.Parallel() + + loc := time.FixedZone("test/zone", 3600) + first := sharedTimestamp(time.RFC3339, loc, 10*time.Millisecond) + second := sharedTimestamp(time.RFC3339, loc, 10*time.Millisecond) + third := sharedTimestamp(time.RFC3339Nano, loc, 10*time.Millisecond) + + require.Same(t, first, second) + require.NotSame(t, first, third) + require.NotEmpty(t, first.Load().(string)) +} + // go test -run Test_Response_Header func Test_Response_Header(t *testing.T) { t.Parallel() diff --git a/middleware/logger/tags.go b/middleware/logger/tags.go index e36e95f3ef2..199dd31280c 100644 --- a/middleware/logger/tags.go +++ b/middleware/logger/tags.go @@ -237,7 +237,7 @@ func createTagMap(cfg *Config) map[string]LogFunc { return fmt.Fprintf(output, "%13v", latency) }, TagTime: func(output Buffer, _ fiber.Ctx, data *Data, _ string) (int, error) { - return output.WriteString(data.Timestamp.Load().(string)) //nolint:forcetypeassert,errcheck // We always store a string in here + return output.WriteString(data.Timestamp) }, } registeredTags.RLock() diff --git a/middleware/logger/timestamp.go b/middleware/logger/timestamp.go new file mode 100644 index 00000000000..959b1b4e1e5 --- /dev/null +++ b/middleware/logger/timestamp.go @@ -0,0 +1,53 @@ +package logger + +import ( + "sync" + "sync/atomic" + "time" +) + +type timestampKey struct { + format string + timeZone string + interval time.Duration +} + +var ( + tsMu sync.RWMutex + tsCache = map[timestampKey]*atomic.Value{} +) + +func sharedTimestamp(format string, location *time.Location, interval time.Duration) *atomic.Value { + key := timestampKey{ + format: format, + timeZone: location.String(), + interval: interval, + } + + tsMu.RLock() + value, ok := tsCache[key] + tsMu.RUnlock() + if ok { + return value + } + + tsMu.Lock() + defer tsMu.Unlock() + + if value, ok = tsCache[key]; ok { + return value + } + + value = &atomic.Value{} + value.Store(time.Now().In(location).Format(format)) + tsCache[key] = value + + go func() { + for { + time.Sleep(interval) + value.Store(time.Now().In(location).Format(format)) + } + }() + + return value +}