Uploaded image for project: 'Advanced Cache'
  1. Advanced Cache
  2. MGNLADVCACHE-116

Site aware caching no longer creates site caches

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Neutral
    • Resolution: Fixed
    • Affects Version/s: 2.3.3
    • Fix Version/s: 2.3.4
    • Component/s: None
    • Sprint:
      Maintenance 67
    • Story Points:
      3

      Description

      By adding some additional logging (MGNLCACHE-231 & MGNLADVCACHE-110) we can see that site aware caching does not seem to be functioning correctly.

      Set your log4j2.xml when using the snapshots from the attached tickets:

          <Logger name="info.magnolia.module.cache" level="ALL"/>
          <Logger name="info.magnolia.module.advancedcache" level="ALL"/>
      

      Recreate:

      • Set your instance for site aware caching.
      • Fill a couple caches with requests from the travel site and sportstation site.
      • Verify the cache filter is serving them from cache and the name of the cache it serves from.
      • Publishing sportstation.
      • Observe requests still coming from sportstation cache which we can now see is not being flushed after publication.
        2020-08-11 18:41:38,094 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=useCache, cacheName=travel, cacheKey=DefaultCacheKey{uri='/travel.html', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=info.magnolia.module.cache.filter.InMemoryCachedEntry@54cf2a64[gzippedContent=5459 bytes,plainContent=24683 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597163944277,originalUrl=http://localhost:8080/dx-core-webapp/travel.html,timeToLiveInSeconds=-1]}
        2020-08-11 18:41:38,094 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@54cf2a64[gzippedContent=5459 bytes,plainContent=24683 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597163944277,originalUrl=http://localhost:8080/dx-core-webapp/travel.html,timeToLiveInSeconds=-1]
        2020-08-11 18:41:38,100 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=store, cacheName=travel, cacheKey=DefaultCacheKey{uri='/travel/main/0', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{mgnlCacheVariant={9b13970f-6b1b-451e-83fc-36cfde37f78e=0}}'}, cachedEntry=null}
        2020-08-11 18:41:38,121 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [browserTtlVoter] fired 2147483647
        2020-08-11 18:41:38,122 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [serverTtlVoter] fired -1
        2020-08-11 18:41:38,122 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: lowestVote vote is now -1
        2020-08-11 18:41:38,129 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@30b9fa97[gzippedContent=914 bytes,plainContent=4033 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList={Last-Modified=[1597164098100]},lastModificationTime=1597164098100,originalUrl=http://localhost:8080/dx-core-webapp/travel/main/0,timeToLiveInSeconds=-1]
        2020-08-11 18:41:38,131 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=store, cacheName=travel, cacheKey=DefaultCacheKey{uri='/travel/main/00', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{mgnlCacheVariant={9b13970f-6b1b-451e-83fc-36cfde37f78e=0}}'}, cachedEntry=null}
        2020-08-11 18:41:38,191 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [browserTtlVoter] fired 2147483647
        2020-08-11 18:41:38,191 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [serverTtlVoter] fired -1
        2020-08-11 18:41:38,191 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: lowestVote vote is now -1
        2020-08-11 18:41:38,194 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@2a8e275f[gzippedContent=660 bytes,plainContent=2432 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList={Last-Modified=[1597164098132]},lastModificationTime=1597164098132,originalUrl=http://localhost:8080/dx-core-webapp/travel/main/00,timeToLiveInSeconds=-1]
        
        
        2020-08-11 18:41:52,700 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=useCache, cacheName=sportstation, cacheKey=DefaultCacheKey{uri='/sportstation.html', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=info.magnolia.module.cache.filter.InMemoryCachedEntry@7bc42522[gzippedContent=3921 bytes,plainContent=32293 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164079373,originalUrl=http://localhost:8080/dx-core-webapp/sportstation.html,timeToLiveInSeconds=-1]}
        2020-08-11 18:41:52,701 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@7bc42522[gzippedContent=3921 bytes,plainContent=32293 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164079373,originalUrl=http://localhost:8080/dx-core-webapp/sportstation.html,timeToLiveInSeconds=-1]
        
        
        2020-08-11 18:42:54,621 INFO  r.operation.jcr.JcrTransactionPublicationOperation: 377:1597164171492 User superuser successfully published website:/sportstation on dx-core-webapp.
        2020-08-11 18:42:59,775 TRACE ule.advancedcache.SiteAwareFlushAllListeningPolicy: Cache flushed: site
        2020-08-11 18:42:59,776 TRACE info.magnolia.module.cache.FlushAllListeningPolicy: Cache flushed: uuid-key-mapping
        2020-08-11 18:42:59,778 TRACE ule.advancedcache.SiteAwareFlushAllListeningPolicy: Cache flushed: defaultPageCache
        
        
        2020-08-11 18:43:30,407 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=useCache, cacheName=travel, cacheKey=DefaultCacheKey{uri='/travel.html', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=info.magnolia.module.cache.filter.InMemoryCachedEntry@54cf2a64[gzippedContent=5459 bytes,plainContent=24683 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597163944277,originalUrl=http://localhost:8080/dx-core-webapp/travel.html,timeToLiveInSeconds=-1]}
        2020-08-11 18:43:30,407 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@54cf2a64[gzippedContent=5459 bytes,plainContent=24683 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597163944277,originalUrl=http://localhost:8080/dx-core-webapp/travel.html,timeToLiveInSeconds=-1]
        2020-08-11 18:43:30,410 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=useCache, cacheName=travel, cacheKey=DefaultCacheKey{uri='/travel/main/0', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{mgnlCacheVariant={9b13970f-6b1b-451e-83fc-36cfde37f78e=0}}'}, cachedEntry=info.magnolia.module.cache.filter.InMemoryCachedEntry@4cddec84[gzippedContent=914 bytes,plainContent=4033 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164098100,originalUrl=http://localhost:8080/dx-core-webapp/travel/main/0,timeToLiveInSeconds=-1]}
        2020-08-11 18:43:30,411 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@4cddec84[gzippedContent=914 bytes,plainContent=4033 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164098100,originalUrl=http://localhost:8080/dx-core-webapp/travel/main/0,timeToLiveInSeconds=-1]
        2020-08-11 18:43:30,413 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=useCache, cacheName=travel, cacheKey=DefaultCacheKey{uri='/travel/main/00', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{mgnlCacheVariant={9b13970f-6b1b-451e-83fc-36cfde37f78e=0}}'}, cachedEntry=info.magnolia.module.cache.filter.InMemoryCachedEntry@5ea1a6d6[gzippedContent=660 bytes,plainContent=2432 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164098132,originalUrl=http://localhost:8080/dx-core-webapp/travel/main/00,timeToLiveInSeconds=-1]}
        2020-08-11 18:43:30,414 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@5ea1a6d6[gzippedContent=660 bytes,plainContent=2432 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164098132,originalUrl=http://localhost:8080/dx-core-webapp/travel/main/00,timeToLiveInSeconds=-1]
        2020-08-11 18:43:30,509 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=store, cacheName=defaultPageCache, cacheKey=DefaultCacheKey{uri='/.imaging/mte/travel-demo-theme/1366/dam/tours/ruben-mishchuk-571314-unsplash/jcr:content/ruben-mishchuk-571314-unsplash.jpg', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=null}
        2020-08-11 18:43:30,509 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=store, cacheName=defaultPageCache, cacheKey=DefaultCacheKey{uri='/.imaging/mte/travel-demo-theme/1366/dam/tours/ash-edmonds-441220-unsplash/jcr:content/ash-edmonds-441220-unsplash.jpg', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=null}
        2020-08-11 18:43:30,509 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=store, cacheName=defaultPageCache, cacheKey=DefaultCacheKey{uri='/.imaging/mte/travel-demo-theme/1366/dam/tours/simon-mumenthaler-199501-unsplash/jcr:content/simon-mumenthaler-199501-unsplash.jpg', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=null}
        2020-08-11 18:43:30,512 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [browserTtlVoter] fired 2147483647
        2020-08-11 18:43:30,512 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [browserTtlVoter] fired 2147483647
        2020-08-11 18:43:30,512 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [serverTtlVoter] fired 2147483647
        2020-08-11 18:43:30,512 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [serverTtlVoter] fired 2147483647
        2020-08-11 18:43:30,512 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [browserTtlVoter] fired 2147483647
        2020-08-11 18:43:30,512 DEBUG magnolia.module.cache.cachepolicy.voters.TtlVoting: voter [serverTtlVoter] fired 2147483647
        2020-08-11 18:43:30,520 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@49a7691c[gzippedContent=115968 bytes,plainContent=121048 bytes,contentType=image/jpeg,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList={Last-Modified=[1597164210509], Content-Type=[image/jpeg]},lastModificationTime=1597164210509,originalUrl=http://localhost:8080/dx-core-webapp/.imaging/mte/travel-demo-theme/1366/dam/tours/simon-mumenthaler-199501-unsplash/jcr:content/simon-mumenthaler-199501-unsplash.jpg,timeToLiveInSeconds=-1]
        2020-08-11 18:43:30,521 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@4dbda4b5[gzippedContent=170959 bytes,plainContent=171169 bytes,contentType=image/jpeg,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList={Last-Modified=[1597164210509], Content-Type=[image/jpeg]},lastModificationTime=1597164210509,originalUrl=http://localhost:8080/dx-core-webapp/.imaging/mte/travel-demo-theme/1366/dam/tours/ash-edmonds-441220-unsplash/jcr:content/ash-edmonds-441220-unsplash.jpg,timeToLiveInSeconds=-1]
        2020-08-11 18:43:30,533 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@62ce6a95[gzippedContent=350291 bytes,plainContent=350324 bytes,contentType=image/jpeg,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList={Last-Modified=[1597164210509], Content-Type=[image/jpeg]},lastModificationTime=1597164210509,originalUrl=http://localhost:8080/dx-core-webapp/.imaging/mte/travel-demo-theme/1366/dam/tours/ruben-mishchuk-571314-unsplash/jcr:content/ruben-mishchuk-571314-unsplash.jpg,timeToLiveInSeconds=-1]
        
        
        2020-08-11 18:43:52,271 DEBUG info.magnolia.module.cache.filter.CacheFilter     : Cache policy result: CachePolicyResult{behaviour=useCache, cacheName=sportstation, cacheKey=DefaultCacheKey{uri='/sportstation.html', serverName='localhost', locale='en', channel='all', params={}', secure='false', method='get', additionalAttributes='{}'}, cachedEntry=info.magnolia.module.cache.filter.InMemoryCachedEntry@7bc42522[gzippedContent=3921 bytes,plainContent=32293 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164079373,originalUrl=http://localhost:8080/dx-core-webapp/sportstation.html,timeToLiveInSeconds=-1]}
        2020-08-11 18:43:52,271 DEBUG info.magnolia.module.cache.executor.UseCache      : Serving info.magnolia.module.cache.filter.InMemoryCachedEntry@7bc42522[gzippedContent=3921 bytes,plainContent=32293 bytes,contentType=text/html,characterEncoding=UTF-8,statusCode=200,serializableHeadersBackingList=<null>,lastModificationTime=1597164079373,originalUrl=http://localhost:8080/dx-core-webapp/sportstation.html,timeToLiveInSeconds=-1]
        

      Expected:
      The sportstation cache should be flushed.

      Workaround:
      Touch the cache config so the cache is restarted with all sites available.

      Notes
      If you look at the entire log site-aware-cache-problem.log you can see I have three sites. One other site called /home. This page seems to be cache with the defaultPageCache.

      2020-08-11 18:39:47,213 DEBUG info.magnolia.module.cache.filter.CacheFilter  : 
      Cache policy result: CachePolicyResult{behaviour=store, cacheName=defaultPageCache, 
      cacheKey=DefaultCacheKey{uri='/home.html', serverName='localhost', locale='en', 
      

      The home site does not have a site definition. However, shouldn't the cache be called "home" as well. It would be great if we could clarify in the instructions how it works.

      When using the workaround of touching the cache config the log reports the caches as being uninitialized. See cache-uninitialized.txt

      Solution
      As hinted below in Viet's comment, site caches were not created correctly upon starting up Magnolia, since multisite module waits until all modules have started in order to register sites. In the same way, advanced cache initialises site aware caches upon ModulesStartedEvent after multisite is done registering sites.

        Checklists

        Acceptance criteria

          Attachments

            Issue Links

              Activity

                People

                Assignee:
                fgrilli Federico Grilli
                Reporter:
                rgange Richard Gange
                Votes:
                2 Vote for this issue
                Watchers:
                6 Start watching this issue

                  Dates

                  Created:
                  Updated:
                  Resolved:
                  Date of First Response:

                    Checklists

                    Bug DoR
                    DoD

                      Time Tracking

                      Estimated:
                      Original Estimate - Not Specified
                      Not Specified
                      Remaining:
                      Remaining Estimate - Not Specified
                      Not Specified
                      Logged:
                      Time Spent - 1h 22m
                      1h 22m