Cache Testing and Monitoring

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132

// Investigation tool for stale data issues
class StaleDataInvestigator {
    constructor(
        private cache: Redis,
        private database: Database,
        private logger: Logger
    ) {}
    
    async investigate(entityType: string, entityId: string): Promise<Investigation> {
        const investigation: Investigation = {
            timestamp: new Date().toISOString(),
            entityType,
            entityId,
            findings: [],
            conclusion: 'unknown',
        };
        
        // Step 1: Get current cache state
        const cacheKey = `${entityType}:${entityId}`;
        const cachedRaw = await this.cache.get(cacheKey);
        const ttl = await this.cache.ttl(cacheKey);
        
        investigation.cacheState = {
            key: cacheKey,
            exists: cachedRaw !== null,
            ttlSeconds: ttl,
            value: cachedRaw ? JSON.parse(cachedRaw) : null,
        };
        
        if (!cachedRaw) {
            investigation.findings.push('Cache entry does not exist');
            investigation.conclusion = 'cache_miss_not_stale_data';
            return investigation;
        }
        
        // Step 2: Get current database state
        const dbValue = await this.database.findById(entityType, entityId);
        investigation.databaseState = {
            value: dbValue,
            lastUpdated: dbValue?.updatedAt,
        };
        
        // Step 3: Compare cache vs database
        const serializedDb = JSON.stringify(dbValue);
        const serializedCache = JSON.stringify(investigation.cacheState.value);
        
        if (serializedDb === serializedCache) {
            investigation.findings.push('Cache matches database - no staleness detected');
            investigation.conclusion = 'cache_consistent';
            return investigation;
        }
        
        investigation.findings.push('STALE DATA DETECTED: Cache differs from database');
        
        // Step 4: Determine cache age
        const cacheTimestamp = investigation.cacheState.value?._cachedAt;
        if (cacheTimestamp) {
            const cacheAge = Date.now() - new Date(cacheTimestamp).getTime();
            investigation.findings.push(`Cache entry is ${Math.round(cacheAge / 1000)}s old`);
            
            // Compare to last database update
            if (dbValue?.updatedAt) {
                const dbUpdateTime = new Date(dbValue.updatedAt).getTime();
                const cacheTime = new Date(cacheTimestamp).getTime();
                
                if (cacheTime < dbUpdateTime) {
                    investigation.findings.push(
                        `Cache was written BEFORE database update (stale by ${Math.round((dbUpdateTime - cacheTime) / 1000)}s)`
                    );
                    investigation.conclusion = 'invalidation_missed';
                } else {
                    investigation.findings.push('Cache was written AFTER database update - possible race condition');
                    investigation.conclusion = 'race_condition';
                }
            }
        }
        
        // Step 5: Check invalidation logs
        const recentInvalidations = await this.logger.query({
            message: 'cache_invalidation',
            key: cacheKey,
            timestamp: { $gt: new Date(Date.now() - 3600000) } // Last hour
        });
        
        investigation.invalidationHistory = recentInvalidations;
        
        if (recentInvalidations.length === 0) {
            investigation.findings.push('No invalidation attempts found in last hour');
        } else {
            investigation.findings.push(`Found ${recentInvalidations.length} invalidation attempt(s)`);
            recentInvalidations.forEach(inv => {
                investigation.findings.push(`  - ${inv.timestamp}: ${inv.result}`);
            });
        }
        
        // Step 6: Check for re-population after invalidation
        const cacheWrites = await this.logger.query({
            message: 'cache_set',
            key: cacheKey,
            timestamp: { $gt: new Date(Date.now() - 3600000) }
        });
        
        if (cacheWrites.length > 1) {
            investigation.findings.push('Multiple cache writes detected - possible re-population with stale data');
            investigation.cacheWriteHistory = cacheWrites;
        }
        
        return investigation;
    }
    
    async generateReport(investigation: Investigation): Promise<string> {
        let report = `
=== STALE DATA INVESTIGATION REPORT ===
Timestamp: ${investigation.timestamp}
Entity: ${investigation.entityType}:${investigation.entityId}
 
CACHE STATE:
  Key: ${investigation.cacheState.key}
  Exists: ${investigation.cacheState.exists}
  TTL: ${investigation.cacheState.ttlSeconds}s remaining
 
DATABASE STATE:
  Last Updated: ${investigation.databaseState?.lastUpdated || 'unknown'}
 
FINDINGS:
${investigation.findings.map(f => '  • ' + f).join('\n')}
 
CONCLUSION: ${investigation.conclusion}
`;
        return report;
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64

// Production-safe cache bypass for debugging
class DebuggableCache<T> implements Cache<T> {
    private bypassedKeys: Set<string> = new Set();
    private globalBypass: boolean = false;
    
    constructor(
        private innerCache: Cache<T>,
        private metrics: CacheMetrics
    ) {}
    
    async get(key: string): Promise<T | null> {
        // Check for bypass conditions
        if (this.globalBypass || this.bypassedKeys.has(key)) {
            this.metrics.recordBypass(key);
            return null; // Force cache miss
        }
        return this.innerCache.get(key);
    }
    
    async set(key: string, value: T, ttlSeconds?: number): Promise<void> {
        if (this.globalBypass || this.bypassedKeys.has(key)) {
            return; // Skip caching entirely
        }
        await this.innerCache.set(key, value, ttlSeconds);
    }
    
    // Debug endpoints (protect with authentication in production!)
    async bypassKey(key: string, durationMs: number = 60000): Promise<void> {
        this.bypassedKeys.add(key);
        console.log(`[CACHE DEBUG] Bypassing key: ${key} for ${durationMs}ms`);
        
        setTimeout(() => {
            this.bypassedKeys.delete(key);
            console.log(`[CACHE DEBUG] Re-enabling key: ${key}`);
        }, durationMs);
    }
    
    async bypassPatternTemporarily(pattern: string, durationMs: number = 60000): Promise<void> {
        // For pattern-based bypassing, set a flag that get() checks
        console.log(`[CACHE DEBUG] Bypassing pattern: ${pattern} for ${durationMs}ms`);
    }
    
    async setGlobalBypass(enabled: boolean): Promise<void> {
        this.globalBypass = enabled;
        console.log(`[CACHE DEBUG] Global bypass: ${enabled}`);
    }
}
 
// API endpoint for debugging (PROTECT THIS!)
app.post('/debug/cache/bypass', authenticate, requireAdmin, async (req, res) => {
    const { key, pattern, duration, global } = req.body;
    
    if (global !== undefined) {
        await cache.setGlobalBypass(global);
        return res.json({ message: `Global bypass set to: ${global}` });
    }
    
    if (key) {
        await cache.bypassKey(key, duration || 60000);
        return res.json({ message: `Bypassing key: ${key}` });
    }
    
    res.status(400).json({ error: 'Specify key, pattern, or global' });
});

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88

# Connect to Redis CLI
redis-cli -h cache-host -p 6379
 
# ===== KEY EXISTENCE AND METADATA =====
 
# Check if specific key exists
EXISTS product:12345
 
# Get key type
TYPE product:12345
 
# Get TTL remaining (seconds)
TTL product:12345
 
# Get TTL remaining (milliseconds, more precise)
PTTL product:12345
 
# Get key's idle time (seconds since last access)
OBJECT IDLETIME product:12345
 
# Get memory usage of specific key
MEMORY USAGE product:12345
 
# ===== EXAMINING VALUES =====
 
# Get string value
GET product:12345
 
# Get hash fields
HGETALL user:profile:789
 
# Get list elements
LRANGE recent-views:456 0 -1
 
# Get set members
SMEMBERS tags:electronics
 
# Get sorted set with scores
ZRANGE leaderboard 0 -1 WITHSCORES
 
# ===== KEY PATTERN SEARCH =====
 
# Find keys matching pattern (CAUTION: blocks on large datasets)
# Use SCAN in production instead
KEYS product:*
 
# Safer: Scan incrementally
SCAN 0 MATCH product:* COUNT 100
 
# Count keys matching pattern
# (Iterate SCAN, count matches - no built-in command)
 
# ===== DEBUGGING SPECIFIC ISSUES =====
 
# Check when key was last modified (if using Redis Streams or custom tracking)
# Note: Redis doesn't track this natively for all data types
 
# See recently modified keys (if using keyspace notifications)
PSUBSCRIBE __keyspace@0__:*
 
# Get all configuration
CONFIG GET *
 
# Get memory statistics
INFO memory
 
# Get cache hit/miss stats
INFO stats
# Look for: keyspace_hits, keyspace_misses
 
# ===== SAFE DATA INSPECTION =====
 
# Dump raw bytes (for binary data or unknown encoding)
DUMP product:12345
 
# Pretty-print JSON (pipe through jq)
GET product:12345 | jq .
 
# ===== CAREFUL WITH THESE IN PRODUCTION =====
 
# Delete a key (for manual fix during debugging)
DEL product:12345
 
# Set a key to expire immediately
EXPIRE product:12345 0
 
# Flush entire database (NEVER DO IN PRODUCTION)
# FLUSHDB

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155

// Comprehensive cache forensics toolkit
class CacheForensics {
    constructor(private redis: Redis) {}
    
    // Get complete snapshot of a key's state
    async keySnapshot(key: string): Promise<KeySnapshot> {
        const [
            exists,
            type,
            ttl,
            idleTime,
            memoryUsage,
            value
        ] = await Promise.all([
            this.redis.exists(key),
            this.redis.type(key),
            this.redis.ttl(key),
            this.redis.object('IDLETIME', key),
            this.redis.memory('USAGE', key),
            this.getValue(key)
        ]);
        
        return {
            key,
            exists: exists === 1,
            type,
            ttlSeconds: ttl,
            idleTimeSeconds: idleTime,
            memoryBytes: memoryUsage,
            value,
            capturedAt: new Date().toISOString(),
        };
    }
    
    // Compare cache value to expected value
    async compareToExpected(key: string, expected: any): Promise<Comparison> {
        const cached = await this.getValue(key);
        
        if (cached === null) {
            return { match: false, reason: 'Key does not exist in cache' };
        }
        
        const differences = this.deepDiff(cached, expected);
        
        return {
            match: differences.length === 0,
            differences,
            cached,
            expected,
        };
    }
    
    // Find all keys for an entity
    async findRelatedKeys(entityId: string): Promise<string[]> {
        const patterns = [
            `*:${entityId}`,
            `*:${entityId}:*`,
            `*:*:${entityId}`,
        ];
        
        const allKeys: string[] = [];
        
        for (const pattern of patterns) {
            let cursor = '0';
            do {
                const [newCursor, keys] = await this.redis.scan(
                    cursor, 'MATCH', pattern, 'COUNT', 100
                );
                cursor = newCursor;
                allKeys.push(...keys);
            } while (cursor !== '0');
        }
        
        return [...new Set(allKeys)]; // Deduplicate
    }
    
    // Track key changes over time
    async watchKey(key: string, intervalMs: number, durationMs: number): Promise<KeyHistory> {
        const history: Array<{timestamp: string; value: any; ttl: number}> = [];
        const startTime = Date.now();
        
        while (Date.now() - startTime < durationMs) {
            const [value, ttl] = await Promise.all([
                this.getValue(key),
                this.redis.ttl(key)
            ]);
            
            history.push({
                timestamp: new Date().toISOString(),
                value,
                ttl,
            });
            
            await new Promise(resolve => setTimeout(resolve, intervalMs));
        }
        
        return { key, history };
    }
    
    // Find keys with abnormal characteristics
    async findAnomalousKeys(pattern: string): Promise<AnomalousKeyReport> {
        const anomalies: AnomalousKey[] = [];
        let cursor = '0';
        
        do {
            const [newCursor, keys] = await this.redis.scan(
                cursor, 'MATCH', pattern, 'COUNT', 100
            );
            cursor = newCursor;
            
            for (const key of keys) {
                const snapshot = await this.keySnapshot(key);
                
                // Check for anomalies
                if (snapshot.ttlSeconds === -1) {
                    anomalies.push({ key, issue: 'No TTL set (immortal key)' });
                }
                if (snapshot.memoryBytes && snapshot.memoryBytes > 1000000) {
                    anomalies.push({ key, issue: `Large key: ${snapshot.memoryBytes} bytes` });
                }
                if (snapshot.idleTimeSeconds && snapshot.idleTimeSeconds > 3600) {
                    anomalies.push({ key, issue: 'Idle for >1 hour (possibly orphaned)' });
                }
            }
        } while (cursor !== '0');
        
        return { pattern, anomalies, scannedAt: new Date().toISOString() };
    }
    
    private async getValue(key: string): Promise<any> {
        const type = await this.redis.type(key);
        
        switch (type) {
            case 'string':
                const str = await this.redis.get(key);
                try { return JSON.parse(str!); } catch { return str; }
            case 'hash':
                return this.redis.hgetall(key);
            case 'list':
                return this.redis.lrange(key, 0, -1);
            case 'set':
                return this.redis.smembers(key);
            case 'zset':
                return this.redis.zrange(key, 0, -1, 'WITHSCORES');
            default:
                return null;
        }
    }
    
    private deepDiff(obj1: any, obj2: any, path: string = ''): string[] {
        const diffs: string[] = [];
        // ... deep diff implementation
        return diffs;
    }
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166

// Framework for reproducing cache race conditions
class CacheRaceConditionReproducer {
    constructor(
        private cache: Cache<any>,
        private database: Database,
        private service: ProductService
    ) {}
    
    // Reproduce: Read returning stale data during write
    async reproduceReadWriteRace(): Promise<ReproductionResult> {
        const productId = 'test-product-race';
        const originalProduct = { id: productId, name: 'Original', version: 1 };
        const updatedProduct = { id: productId, name: 'Updated', version: 2 };
        
        // Setup: Cache and database have original
        await this.database.insert(originalProduct);
        await this.cache.set(`product:${productId}`, originalProduct, 3600);
        
        // Race: Start read, update, complete read
        const results: any[] = [];
        
        // Create a read that will definitely see the old value
        const slowRead = new Promise(async (resolve) => {
            // Simulate a slow read that starts before update
            const cached = await this.cache.get(`product:${productId}`);
            await sleep(100); // Processing delay
            resolve({ operation: 'read', value: cached });
        });
        
        // Update that invalidates cache
        const update = new Promise(async (resolve) => {
            await sleep(10); // Start slightly after read
            await this.database.update(productId, updatedProduct);
            await this.cache.delete(`product:${productId}`);
            resolve({ operation: 'update', completed: true });
        });
        
        // Another read that happens after invalidation but uses stale variable
        const stalePossibleRead = new Promise(async (resolve) => {
            await sleep(120); // After update completes
            const result = await this.service.getProduct(productId);
            resolve({ operation: 'subsequentRead', value: result });
        });
        
        const allResults = await Promise.all([slowRead, update, stalePossibleRead]);
        
        // Analyze: Did the race occur?
        const subsequentReadResult = allResults.find(r => r.operation === 'subsequentRead');
        const hasStaleData = subsequentReadResult?.value?.version === 1;
        
        return {
            raceOccurred: hasStaleData,
            timeline: allResults,
            analysis: hasStaleData 
                ? 'BUG: Subsequent read returned stale data (v1 instead of v2)'
                : 'PASS: Subsequent read correctly returned updated data',
        };
    }
    
    // Reproduce: Cache stampede on expiration
    async reproduceStampede(concurrency: number = 100): Promise<StampedeResult> {
        const productId = 'test-product-stampede';
        const product = { id: productId, name: 'Popular Product' };
        
        // Setup: Cache with very short TTL
        await this.database.insert(product);
        await this.cache.set(`product:${productId}`, product, 1); // 1 second TTL
        
        // Wait for expiration
        await sleep(1100);
        
        // Stampede: Many concurrent requests hitting expired cache
        const requestStartTimes: number[] = [];
        const databaseHits: number[] = [];
        let dbQueryCount = 0;
        
        const interceptedDatabase = new Proxy(this.database, {
            get(target, prop) {
                if (prop === 'findById') {
                    return async (...args: any[]) => {
                        dbQueryCount++;
                        databaseHits.push(Date.now());
                        return target.findById(...args);
                    };
                }
                return target[prop as keyof Database];
            }
        });
        
        const service = new ProductService(this.cache, interceptedDatabase);
        
        // Fire concurrent requests
        const requests = Array.from({ length: concurrency }, async () => {
            requestStartTimes.push(Date.now());
            return service.getProduct(productId);
        });
        
        await Promise.all(requests);
        
        return {
            totalRequests: concurrency,
            databaseQueryCount: dbQueryCount,
            stampedeOccurred: dbQueryCount > 1,
            analysis: dbQueryCount > 1
                ? `STAMPEDE: ${dbQueryCount} database hits instead of 1`
                : 'PROTECTED: Only 1 database hit despite concurrent requests',
            timeline: {
                requestStarts: requestStartTimes,
                databaseHits,
            },
        };
    }
    
    // Reproduce: Invalidation race condition
    async reproduceInvalidationRace(): Promise<InvalidationRaceResult> {
        const productId = 'test-product-invalidation-race';
        
        // Timing scenario:
        // T0: Read starts (cache miss, starts DB fetch)
        // T1: Update happens (invalidates cache)
        // T2: Read completes (writes OLD data to cache)
        // T3: Subsequent reads get stale data!
        
        const v1 = { id: productId, name: 'Version 1', version: 1 };
        const v2 = { id: productId, name: 'Version 2', version: 2 };
        
        // Database starts with v1
        await this.database.insert(v1);
        
        // Simulate slow fetch that gets v1
        const slowFetch = async (): Promise<any> => {
            const data = await this.database.findById(productId); // Gets v1
            await sleep(200); // Slow network/processing
            return data;
        };
        
        // Start slow fetch
        const fetchPromise = slowFetch();
        
        // While fetch is in progress, update to v2
        await sleep(50);
        await this.database.update(productId, v2);
        await this.cache.delete(`product:${productId}`);
        
        // Fetch completes and writes v1 to cache
        const fetchedData = await fetchPromise;
        await this.cache.set(`product:${productId}`, fetchedData, 3600);
        
        // Check what's in cache now
        const cachedValue = await this.cache.get(`product:${productId}`);
        const dbValue = await this.database.findById(productId);
        
        return {
            raceOccurred: cachedValue?.version !== dbValue?.version,
            cachedVersion: cachedValue?.version,
            databaseVersion: dbValue?.version,
            analysis: cachedValue?.version === 1 && dbValue?.version === 2
                ? 'BUG: Cache contains v1 but database has v2 (invalidation race)'
                : 'PASS: Cache and database are consistent',
        };
    }
}
 
function sleep(ms: number): Promise<void> {
    return new Promise(resolve => setTimeout(resolve, ms));
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83

// Verify fixes for common cache bugs
describe('Cache Bug Fix Verification', () => {
    
    describe('Invalidation Fix Verification', () => {
        it('should return fresh data immediately after update', async () => {
            // Setup: Cache old data
            const original = { id: 'prod-1', name: 'Original', price: 10 };
            await service.getProduct('prod-1'); // Populates cache
            
            // Update
            const updated = { id: 'prod-1', name: 'Updated', price: 20 };
            await service.updateProduct('prod-1', updated);
            
            // Verify: Immediate read returns updated data
            const result = await service.getProduct('prod-1');
            expect(result.price).toBe(20);
        });
        
        it('should invalidate related caches on entity update', async () => {
            // Setup: Populate multiple related caches
            await service.getProduct('prod-1');           // product:prod-1
            await service.getProductsByCategory('cat-1'); // category:cat-1:products
            await service.getInventory('prod-1');         // inventory:prod-1
            
            // Update product
            await service.updateProduct('prod-1', { name: 'Updated' });
            
            // Verify: All related caches should be invalidated
            expect(await cache.get('product:prod-1')).toBeNull();
            expect(await cache.get('category:cat-1:products')).toBeNull();
            expect(await cache.get('inventory:prod-1')).toBeNull();
        });
    });
    
    describe('Stampede Prevention Verification', () => {
        it('should make exactly one database query under concurrent load', async () => {
            // Clear cache
            await cache.clear();
            
            // Fire 100 concurrent requests
            const requests = Array.from({ length: 100 }, () => 
                service.getProduct('prod-1')
            );
            
            await Promise.all(requests);
            
            // Verify: Only one database hit
            expect(database.queryCount).toBe(1);
        });
    });
    
    describe('Race Condition Fix Verification', () => {
        it('should not cache stale data during concurrent update', async () => {
            const results: number[] = [];
            
            // Run many iterations to catch probabilistic races
            for (let i = 0; i < 100; i++) {
                await cache.clear();
                
                // Setup: Start with v1
                database.setProduct('prod-1', { version: 1 });
                
                // Concurrent: Read (which populates cache) and update (which invalidates)
                await Promise.all([
                    service.getProduct('prod-1'),
                    (async () => {
                        await sleep(5); // Small delay
                        database.setProduct('prod-1', { version: 2 });
                        await service.invalidateProduct('prod-1');
                    })(),
                ]);
                
                // Final read should always get v2
                const final = await service.getProduct('prod-1');
                results.push(final.version);
            }
            
            // All iterations should return v2
            const staleCount = results.filter(v => v === 1).length;
            expect(staleCount).toBe(0);
        });
    });
});