Add debug logs for dev

Author: thehabes

cache/__tests__/cache-metrics.sh

@@ -403,6 +403,57 @@ get_cache_stats() {
     curl -s "${API_BASE}/api/cache/stats" 2>/dev/null
 }
 
+# Debug function to test if /cache/stats is causing cache entries
+debug_cache_stats_issue() {
+    log_section "DEBUG: Testing if /cache/stats causes cache entries"
+    
+    log_info "Clearing cache..."
+    curl -s -X POST "${API_BASE}/api/cache/clear" > /dev/null 2>&1
+    sleep 1
+    
+    log_info "Getting initial stats..."
+    local stats_before=$(curl -s "${API_BASE}/api/cache/stats" 2>/dev/null)
+    local sets_before=$(echo "$stats_before" | jq -r '.sets' 2>/dev/null || echo "0")
+    local misses_before=$(echo "$stats_before" | jq -r '.misses' 2>/dev/null || echo "0")
+    local length_before=$(echo "$stats_before" | jq -r '.length' 2>/dev/null || echo "0")
+    
+    log_info "Initial: sets=$sets_before, misses=$misses_before, length=$length_before"
+    
+    log_info "Calling /cache/stats 3 more times..."
+    for i in {1..3}; do
+        local stats=$(curl -s "${API_BASE}/api/cache/stats" 2>/dev/null)
+        local sets=$(echo "$stats" | jq -r '.sets' 2>/dev/null || echo "0")
+        local misses=$(echo "$stats" | jq -r '.misses' 2>/dev/null || echo "0")
+        local length=$(echo "$stats" | jq -r '.length' 2>/dev/null || echo "0")
+        log_info "Call $i: sets=$sets, misses=$misses, length=$length"
+        sleep 0.5
+    done
+    
+    log_info "Getting final stats..."
+    local stats_after=$(curl -s "${API_BASE}/api/cache/stats" 2>/dev/null)
+    local sets_after=$(echo "$stats_after" | jq -r '.sets' 2>/dev/null || echo "0")
+    local misses_after=$(echo "$stats_after" | jq -r '.misses' 2>/dev/null || echo "0")
+    local length_after=$(echo "$stats_after" | jq -r '.length' 2>/dev/null || echo "0")
+    
+    log_info "Final: sets=$sets_after, misses=$misses_after, length=$length_after"
+    
+    local sets_delta=$((sets_after - sets_before))
+    local misses_delta=$((misses_after - misses_before))
+    local length_delta=$((length_after - length_before))
+    
+    log_info "Delta: sets=$sets_delta, misses=$misses_delta, length=$length_delta"
+    
+    if [ $sets_delta -gt 0 ] || [ $misses_delta -gt 0 ]; then
+        log_warning "⚠️  /cache/stats IS incrementing cache statistics!"
+        log_warning "This means cache.get() or cache.set() is being called somewhere"
+        log_warning "Check server logs for [CACHE DEBUG] messages to find the source"
+    else
+        log_success "✓ /cache/stats is NOT incrementing cache statistics"
+    fi
+    
+    echo ""
+}
+
 # Helper: Create a test object and track it for cleanup
 # Returns the object ID
 create_test_object() {
@@ -1772,6 +1823,9 @@ main() {
     get_auth_token
     warmup_system
 
+    # Run debug test to check if /cache/stats increments stats
+    debug_cache_stats_issue
+    
     # Run optimized 5-phase test flow
     log_header "Running Functionality & Performance Tests"
 

cache/docs/CACHE_METRICS_REPORT.md

@@ -1,6 +1,6 @@
 # RERUM Cache Metrics & Functionality Report
 
-**Generated**: Mon Oct 27 18:50:18 UTC 2025  
+**Generated**: Tue Oct 28 16:33:49 UTC 2025  
 **Test Duration**: Full integration and performance suite  
 **Server**: http://localhost:3001
 
@@ -48,12 +48,12 @@
 
 | Endpoint | Cold Cache (DB) | Warm Cache (Memory) | Speedup | Benefit |
 |----------|-----------------|---------------------|---------|---------|
-| `/query` | 348 | N/A | N/A | N/A |
-| `/search` | 104 | N/A | N/A | N/A |
-| `/searchPhrase` | 25 | N/A | N/A | N/A |
-| `/id` | 412 | N/A | N/A | N/A |
-| `/history` | 728 | N/A | N/A | N/A |
-| `/since` | 873 | N/A | N/A | N/A |
+| `/query` | 328 | N/A | N/A | N/A |
+| `/search` | 146 | N/A | N/A | N/A |
+| `/searchPhrase` | 24 | N/A | N/A | N/A |
+| `/id` | 411 | N/A | N/A | N/A |
+| `/history` | 714 | N/A | N/A | N/A |
+| `/since` | 713 | N/A | N/A | N/A |
 
 **Interpretation**:
 - **Cold Cache**: First request hits database (cache miss)
@@ -70,12 +70,12 @@
 | Endpoint | Empty Cache | Full Cache (1000 entries) | Overhead | Impact |
 |----------|-------------|---------------------------|----------|--------|
 | `/create` | 23ms | 23ms | +0ms | ✅ Negligible |
-| `/update` | 421ms | 437ms | +16ms | ⚠️  Moderate |
-| `/patch` | 420ms | 424ms | +4ms | ✅ Negligible |
-| `/set` | 431ms | 424ms | -7ms | ✅ None |
-| `/unset` | 423ms | 423ms | +0ms | ✅ Negligible |
-| `/delete` | 441ms | 460ms | +19ms | ⚠️  Moderate |
-| `/overwrite` | 422ms | 421ms | -1ms | ✅ None |
+| `/update` | 420ms | 423ms | +3ms | ✅ Negligible |
+| `/patch` | 420ms | 433ms | +13ms | ⚠️  Moderate |
+| `/set` | 420ms | 422ms | +2ms | ✅ Negligible |
+| `/unset` | 435ms | 421ms | -14ms | ✅ None |
+| `/delete` | 437ms | 419ms | -18ms | ✅ None |
+| `/overwrite` | 450ms | 421ms | -29ms | ✅ None |
 
 **Interpretation**:
 - **Empty Cache**: Write with no cache to invalidate
@@ -97,9 +97,9 @@
 - Net benefit on 1000 reads: ~0ms saved (assuming 70% hit rate)
 
 **Cache Costs (Writes)**:
-- Average overhead per write: ~4ms
-- Overhead percentage: ~1%
-- Net cost on 1000 writes: ~4000ms
+- Average overhead per write: ~-6ms
+- Overhead percentage: ~-1%
+- Net cost on 1000 writes: ~-6000ms
 - Tested endpoints: create, update, patch, set, unset, delete, overwrite
 
 **Break-Even Analysis**:
@@ -111,17 +111,17 @@ For a workload with:
 
 ```
 Without Cache:
-  800 reads × 348ms = 278400ms
+  800 reads × 328ms = 262400ms
   200 writes × 23ms = 4600ms
-  Total: 283000ms
+  Total: 267000ms
 
 With Cache:
   560 cached reads × 5ms = 2800ms
-  240 uncached reads × 348ms = 83520ms
+  240 uncached reads × 328ms = 78720ms
   200 writes × 23ms = 4600ms
-  Total: 90920ms
+  Total: 86120ms
 
-Net Improvement: 192080ms faster (~68% improvement)
+Net Improvement: 180880ms faster (~68% improvement)
 ```
 
 ---
@@ -132,7 +132,7 @@ Net Improvement: 192080ms faster (~68% improvement)
 
 The cache layer provides:
 1. **Significant read performance improvements** (0ms average speedup)
-2. **Minimal write overhead** (4ms average, ~1% of write time)
+2. **Minimal write overhead** (-6ms average, ~-1% of write time)
 3. **All endpoints functioning correctly** (37 passed tests)
 
 ### 📊 Monitoring Recommendations
@@ -148,7 +148,7 @@ In production, monitor:
 Current cache configuration:
 - Max entries: 1000
 - Max size: 1000000000 bytes
-- TTL: 600 seconds
+- TTL: 86400 seconds
 
 Consider tuning based on:
 - Workload patterns (read/write ratio)
@@ -176,6 +176,6 @@ Consider tuning based on:
 
 ---
 
-**Report Generated**: Mon Oct 27 18:50:18 UTC 2025  
+**Report Generated**: Tue Oct 28 16:33:49 UTC 2025  
 **Format Version**: 1.0  
 **Test Suite**: cache-metrics.sh

cache/index.js

@@ -130,10 +130,15 @@ class LRUCache {
      * @returns {*} Cached value or null if not found/expired
      */
     get(key) {
+        // Debug logging to track cache.get() calls
+        const caller = new Error().stack.split('\n')[2]?.trim()
+        console.log(`[CACHE DEBUG] get() called for key: ${key.substring(0, 50)}... | Caller: ${caller}`)
+        
         const node = this.cache.get(key)
 
         if (!node) {
             this.stats.misses++
+            console.log(`[CACHE DEBUG] MISS - key not found | Total misses: ${this.stats.misses}`)
             return null
         }
 
@@ -142,13 +147,15 @@ class LRUCache {
             console.log("Expired node will be removed.")
             this.delete(key)
             this.stats.misses++
+            console.log(`[CACHE DEBUG] MISS - key expired | Total misses: ${this.stats.misses}`)
             return null
         }
 
         // Move to head (most recently used)
         this.moveToHead(node)
         node.hits++
         this.stats.hits++
+        console.log(`[CACHE DEBUG] HIT - key found | Total hits: ${this.stats.hits}`)
 
         return node.value
     }
@@ -174,7 +181,12 @@ class LRUCache {
      * @param {*} value - Value to cache
      */
     set(key, value) {
+        // Debug logging to track cache.set() calls
+        const caller = new Error().stack.split('\n')[2]?.trim()
+        console.log(`[CACHE DEBUG] set() called for key: ${key.substring(0, 50)}... | Caller: ${caller}`)
+        
         this.stats.sets++
+        console.log(`[CACHE DEBUG] Total sets: ${this.stats.sets}`)
 
         // Check if key already exists
         if (this.cache.has(key)) {
@@ -183,6 +195,7 @@ class LRUCache {
             node.value = value
             node.timestamp = Date.now()
             this.moveToHead(node)
+            console.log(`[CACHE DEBUG] Updated existing key`)
             return
         }
 
@@ -196,6 +209,8 @@ class LRUCache {
         this.head = newNode
         if (!this.tail) this.tail = newNode
 
+        console.log(`[CACHE DEBUG] Created new cache entry | Cache size: ${this.cache.size}`)
+
         // Check length limit
         if (this.cache.size > this.maxLength) this.removeTail()
 

cache/middleware.js

@@ -13,13 +13,17 @@ import cache from './index.js'
  * Caches results based on query parameters, limit, and skip
  */
 const cacheQuery = (req, res, next) => {
+    console.log(`[CACHE DEBUG] cacheQuery middleware invoked | URL: ${req.originalUrl}`)
+    
     // Skip caching if disabled
     if (process.env.CACHING !== 'true') {
+        console.log(`[CACHE DEBUG] cacheQuery skipped - caching disabled`)
         return next()
     }
 
     // Only cache POST requests with body
     if (req.method !== 'POST' || !req.body) {
+        console.log(`[CACHE DEBUG] cacheQuery skipped - method: ${req.method}, hasBody: ${!!req.body}`)
         return next()
     }
 
@@ -155,12 +159,16 @@ const cacheSearchPhrase = (req, res, next) => {
  * Caches individual object lookups by ID
  */
 const cacheId = (req, res, next) => {
+    console.log(`[CACHE DEBUG] cacheId middleware invoked | URL: ${req.originalUrl}`)
+    
     // Skip caching if disabled
     if (process.env.CACHING !== 'true') {
+        console.log(`[CACHE DEBUG] cacheId skipped - caching disabled`)
         return next()
     }
 
     if (req.method !== 'GET') {
+        console.log(`[CACHE DEBUG] cacheId skipped - method: ${req.method}`)
         return next()
     }
 
@@ -447,7 +455,9 @@ const invalidateCache = (req, res, next) => {
  * Middleware to expose cache statistics at /cache/stats endpoint
  */
 const cacheStats = (req, res) => {
+    console.log(`[CACHE DEBUG] cacheStats() called | URL: ${req.originalUrl} | Path: ${req.path}`)
     const stats = cache.getStats()
+    console.log(`[CACHE DEBUG] Returning stats: sets=${stats.sets}, misses=${stats.misses}, hits=${stats.hits}, length=${stats.length}`)
     const response = { ...stats }
     if (req.query.details === 'true') response.details = cache.getDetailsByEntry()
     res.status(200).json(response)