Debugging AEM Dispatcher Cache Invalidation Post-Mortem

At 6:47 AM on Black Friday, our retail client's monitoring dashboard lit up: 23% of product detail pages were serving prices from Wednesday—before the doorbuster discounts went live. With significant revenue at stake during their biggest sales event, we had to diagnose a Dispatcher cache invalidation failure under live production traffic. Here's the deep technical breakdown.

Understanding AEM Dispatcher Cache

Before diving into the incident, let's review how AEM Dispatcher cache invalidation works—because the bug exploited a subtle interaction between two mechanisms.

The .stat File Mechanism

Dispatcher uses .stat files as invalidation markers. When content is published:

1. AEM publish triggers a flush request to Dispatcher
2. Dispatcher "touches" the .stat file (updates its timestamp)
3. On next request, Dispatcher compares cached file's mtime vs .stat mtime
4. If cached file is older than .stat, it's considered stale

                     PUBLISH EVENT
                          │
                          ▼
            ┌─────────────────────────┐
            │     AEM Publisher       │
            │  (activates content)    │
            └───────────┬─────────────┘
                        │ Flush Agent
                        ▼
            ┌─────────────────────────┐
            │      Dispatcher         │
            │  (receives invalidation)│
            └───────────┬─────────────┘
                        │
           ┌────────────┴────────────┐
           │                         │
           ▼                         ▼
    ┌─────────────┐          ┌─────────────┐
    │ Touch .stat │          │ Delete file │
    │   (auto)    │          │  (explicit) │
    └─────────────┘          └─────────────┘

The statfileslevel Configuration

The statfileslevel setting controls which directories get their own .stat file:

# dispatcher.any excerpt
/cache {
    /docroot "/var/www/html"
    /statfileslevel "2"
    
    # With level 2, .stat files exist at:
    # /var/www/html/.stat
    # /var/www/html/content/.stat  
    # /var/www/html/content/site/.stat
    # But NOT deeper (content/site/products/.stat)
}

The Incident: What Went Wrong

Initial Detection

Monitoring caught the issue via price mismatch alerts. Our synthetic monitoring was comparing rendered prices against the PIM (Product Information Management) system:

// Simplified monitoring check
async function checkPriceConsistency(productId) {
    const [webPrice, pimPrice] = await Promise.all([
        scrapePrice(productId),
        getPIMPrice(productId)
    ]);
    
    if (webPrice !== pimPrice) {
        alert({
            severity: 'HIGH',
            message: `Price mismatch: ${productId}`,
            expected: pimPrice,
            actual: webPrice,
            delta: webPrice - pimPrice
        });
    }
}

// Alert at 6:47 AM:
// "Price mismatch: SKU-BF2025-TV65 
//  Expected: $399.99 (Black Friday price)
//  Actual: $899.99 (regular price)"

Scope Assessment

Quick analysis revealed the pattern:

• Affected: 23% of product pages (8,247 of 35,856 products)
• Pattern: All affected products were in specific categories
• Timing: Products published after 11 PM Wednesday showed correct prices

Root Cause Investigation

Step 1: Verify Flush Agent Execution

First, we checked if the flush agents actually fired during the bulk price update:

# Check AEM publish logs for flush activity
grep "Flushing" /opt/aem/crx-quickstart/logs/replication.log | \
    grep "2025-11-27" | tail -20

# Output showed flush events DID fire:
27.11.2025 22:15:03 - Flushing /content/site/us/en/products
27.11.2025 22:15:03 - Flushing /content/site/us/en/products/electronics  
27.11.2025 22:15:04 - Flushing /content/site/us/en/products/electronics/tv
# ... 8000+ more entries

Step 2: Check Dispatcher Receipt

Next, verify Dispatcher received the invalidation requests:

# Dispatcher access logs for FLUSH requests
grep "FLUSH" /var/log/httpd/dispatcher.log | \
    grep "Nov 27" | wc -l
# Result: 8,247 flush requests received ✓

# Check for errors
grep "FLUSH" /var/log/httpd/dispatcher.log | \
    grep "Nov 27" | grep -i "error\|fail"
# Result: 0 errors

Step 3: Examine .stat File Timestamps

Here's where it got interesting:

# Check .stat files in the affected paths
find /var/www/html/content/site/us/en/products -name ".stat" -exec ls -la {} \;

# Output:
-rw-r--r-- 1 apache apache 0 Nov 27 22:15 /var/www/html/content/.stat
-rw-r--r-- 1 apache apache 0 Nov 27 22:15 /var/www/html/content/site/.stat
-rw-r--r-- 1 apache apache 0 Nov 27 22:15 /var/www/html/content/site/us/.stat
# So far so good...

# But check the cached file timestamps:
ls -la /var/www/html/content/site/us/en/products/electronics/tv/samsung-65/*.html

-rw-r--r-- 1 apache apache 45678 Nov 27 22:30 index.html
# Wait - the cached file is NEWER than .stat (22:30 > 22:15)

The Race Condition

Here's what happened during the bulk price update:

TIMELINE (Nov 27)
─────────────────────────────────────────────────────────────────────

22:00   Bulk price update job starts
        │
22:15   First batch completes, triggers flush
        │   ├── .stat files touched (timestamp: 22:15)
        │   └── Cached files deleted
        │
22:16   HIGH TRAFFIC hits site (pre-Black Friday browsing)
        │   └── Dispatcher re-caches pages from PUBLISH
        │       └── But publish still has OLD prices (replication queue)
        │       └── Cached files now have timestamp 22:16-22:30
        │
22:45   Bulk price update completes
        │   └── Second flush triggered
        │       └── .stat touched AGAIN (timestamp: 22:45)
        │       
22:46   Problem: Some cached files from 22:16-22:30 are
        │        OLDER than new .stat (22:45) ✓
        │        But some cached from 22:31+ are NEWER ✗
        │
06:00   Black Friday traffic starts
        │   └── 23% of pages serve stale cache

Why Only Some Pages?

The race condition affected pages that were:

1. Flushed in the first batch (22:15)
2. Re-cached by traffic before update completed (22:16-22:30)
3. In paths covered by the same .stat file (statfileslevel issue)
4. NOT re-flushed because the bulk job used path-based invalidation

The Fix: Multi-Pronged Approach

Immediate Fix (Production - 47 minutes)

We couldn't wait for a proper fix. Immediate action:

# Nuclear option: Force full cache clear for affected paths
# Run on all Dispatcher instances

curl -X POST "http://localhost/dispatcher/invalidate.cache" \
    -H "CQ-Action: Delete" \
    -H "CQ-Handle: /content/site/us/en/products/electronics/tv" \
    -H "CQ-Path: /content/site/us/en/products/electronics/tv"

curl -X POST "http://localhost/dispatcher/invalidate.cache" \
    -H "CQ-Action: Delete" \
    -H "CQ-Handle: /content/site/us/en/products/electronics/audio" \
    -H "CQ-Path: /content/site/us/en/products/electronics/audio"

# Verify cache cleared
ls /var/www/html/content/site/us/en/products/electronics/tv/
# Should be empty or minimal

Configuration Fix (Deployed same day)

1. Increase statfileslevel

# Before: statfileslevel "2"
# After: statfileslevel "4"

/cache {
    /docroot "/var/www/html"
    /statfileslevel "4"
    
    # Now .stat files at:
    # /var/www/html/content/site/us/en/.stat
    # This means each locale has independent invalidation
}

2. Add gracePeriod

/cache {
    # Grace period: treat cache as stale for N seconds after .stat touch
    # This prevents the race condition window
    /gracePeriod "300"
    
    # For 5 minutes after invalidation, ALL requests go to publish
    # Even if cached file appears "newer"
}

3. Implement Resource-Based Invalidation

/cache {
    /invalidate {
        /0000 { /glob "*" /type "deny" }
        /0001 { /glob "*.html" /type "allow" }
    }
    
    /invalidateHandler "/bin/custom-invalidate"
    
    # Custom invalidation handler deletes specific files
    # instead of relying solely on .stat mechanism
}

Application Fix (Deployed next sprint)

We implemented a custom Sling servlet to handle bulk invalidations atomically:

@Component(service = Servlet.class)
@SlingServletPaths("/bin/bulk-price-invalidate")
public class BulkPriceInvalidationServlet extends SlingAllMethodsServlet {
    
    @Reference
    private Replicator replicator;
    
    @Reference
    private ResourceResolverFactory resolverFactory;
    
    @Override
    protected void doPost(SlingHttpServletRequest request, 
                          SlingHttpServletResponse response) {
        
        String[] paths = request.getParameterValues("path");
        
        try (ResourceResolver resolver = getServiceResolver()) {
            // Step 1: Pause Dispatcher flush agents
            pauseFlushAgents();
            
            // Step 2: Complete ALL content updates
            for (String path : paths) {
                updatePriceContent(resolver, path);
            }
            resolver.commit();
            
            // Step 3: Wait for replication queue to clear
            waitForReplicationQueue();
            
            // Step 4: Single atomic flush
            for (String path : paths) {
                replicator.replicate(
                    resolver.adaptTo(Session.class),
                    ReplicationActionType.DELETE,  // Force delete, not .stat
                    path
                );
            }
            
            // Step 5: Resume flush agents
            resumeFlushAgents();
            
            response.getWriter().write("Bulk invalidation complete");
            
        } catch (Exception e) {
            log.error("Bulk invalidation failed", e);
            response.setStatus(500);
        }
    }
    
    private void waitForReplicationQueue() throws InterruptedException {
        // Poll replication queue until empty
        while (getQueueLength() > 0) {
            Thread.sleep(1000);
        }
        // Additional safety buffer
        Thread.sleep(5000);
    }
}

Monitoring Improvements

# New monitoring: Cache consistency check
import requests
from datetime import datetime, timedelta

def check_cache_freshness():
    """
    Compare Dispatcher cache timestamps against 
    last known publish time for critical pages
    """
    
    critical_pages = get_critical_product_pages()
    
    for page in critical_pages:
        # Get cache metadata from Dispatcher
        cache_info = requests.head(
            f"https://www.retailsite.com{page}",
            headers={"X-Dispatcher-Info": "true"}
        )
        
        cache_age = cache_info.headers.get('X-Cache-Age', 0)
        last_modified = cache_info.headers.get('Last-Modified')
        
        # Get last publish time from AEM
        publish_time = get_last_publish_time(page)
        
        # Alert if cache is older than last publish
        if parse_date(last_modified) < publish_time:
            alert({
                'severity': 'HIGH',
                'message': f'Stale cache detected: {page}',
                'cache_time': last_modified,
                'publish_time': publish_time.isoformat()
            })

def monitor_stat_files():
    """
    Monitor .stat file timestamps across all Dispatcher instances
    """
    dispatchers = ['disp1.internal', 'disp2.internal', 'disp3.internal']
    
    stat_times = {}
    for disp in dispatchers:
        stat_times[disp] = get_stat_timestamp(disp, '/var/www/html/content/.stat')
    
    # Alert if .stat files are out of sync > 60 seconds
    max_diff = max(stat_times.values()) - min(stat_times.values())
    if max_diff > 60:
        alert({
            'severity': 'MEDIUM',
            'message': f'.stat file sync drift: {max_diff}s',
            'details': stat_times
        })

Dispatcher Cache Configuration Best Practices

Based on this incident and our experience across dozens of AEM implementations:

Lessons Learned

1. statfileslevel Is Critical for Large Sites

The default level of 0-2 is insufficient for sites with deep content hierarchies. Every level adds granularity but also .stat file overhead. Test your specific content structure.

2. Bulk Operations Need Special Handling

Standard page-by-page invalidation doesn't work for bulk updates. The publish-flush-cache cycle must be atomic across the entire batch.

3. High Traffic Amplifies Race Conditions

This bug existed for months but never surfaced—traffic was low enough that caches weren't re-populated during the race window. Black Friday traffic exposed the latent bug.

4. Monitor Cache Freshness, Not Just Availability

Standard uptime monitoring (is the page loading?) didn't catch this. You need content-aware monitoring that validates the served content matches expected state.