grails 2.4.2 ehcache plugin 1.0.5 evicts keys prematurely

Question

Using grails 2.4.2, cache:1.1.8 and cache-ehcache:1.0.5, I find the cache only holds a single entry. As soon as a second entry is added, the first one disappears.

Configuration

BuildConfig.groovy:

compile ":cache:1.1.8"
compile ":cache-ehcache:1.0.5"

Config.groovy:

grails.hibernate.cache.queries = true

grails {
  cache {
    order = 2000
    enabled = true
    clearAtStartup = true
    shared = true
    ehcache {
      reloadable = false
    }
  }
}

grails.cache.clearAtStartup = true

grails.cache.config = {
  cache {
    name 'siteSettings'
  }
  provider {
    updateCheck false
    monitoring 'on'
    dynamicConfig false
  }
  defaultCache {
    maxElementsInMemory 10000
    timeToIdleSeconds 600
    timeToLiveSeconds 600
    overflowToDisk false
    diskPersistent false
    memoryStoreEvictionPolicy 'LRU'
  }
  defaults {
    maxElementsInMemory 10000
    timeToIdleSeconds 600
    timeToLiveSeconds 600
    overflowToDisk false
    diskPersistent false
    memoryStoreEvictionPolicy 'LRU'
  }
}

cached method in SettingsService.groovy:

@Cacheable(value='siteSettings')
public JSONElement getSiteSettings(Integer site){
  log.info "NOT CACHED for this request (${site})"

Logging Output

1) first request where site=229 (nothing cached):

    Initialised cache: siteSettings
    CacheDecoratorFactory not configured for defaultCache. Skipping for 'siteSettings'.
    siteSettings size: 0
    cacheKeys: 0
    NOT CACHED for this request (229)
    put at siteSettings: [ key = grails.plugin.cache.CustomCacheKeyGenerator$CacheKey@490f0efa, value={"test":229}, version=1, hitCount=3, CreationTime = 1489534645017, LastAccessTime = 1489534976819 ]

2) second request where site=229 (cache holds 229):

    siteSettings size: 1
    cacheKeys: 1
    key 229: [test:229]

3) first request where site=282 (cache holds 229):

    siteSettings size: 1
    cacheKeys: 1
    key 229: [test:229]
    NOT CACHED for this request (282)
    evicted from siteSettings: [ key = grails.plugin.cache.CustomCacheKeyGenerator$CacheKey@490f0efa, value={"test":229}, version=1, hitCount=3, CreationTime = 1489534645017, LastAccessTime = 1489534976819 ]
    put at siteSettings: [ key = grails.plugin.cache.CustomCacheKeyGenerator$CacheKey@492726a5, value={"test":282}, version=1, hitCount=0, CreationTime = 1489534976848, LastAccessTime = 1489534976848 ]

4) second request where site=282 (cache holds 282, not 229):

    siteSettings size: 1
    cacheKeys: 1
    key 282: [test:282]

5) third request where site=229 (cache holds 282, not 229):

    siteSettings size: 1
    cacheKeys: 1
    key 282: [test:282]
    NOT CACHED for this request (229)
    evicted from siteSettings: [ key = grails.plugin.cache.CustomCacheKeyGenerator$CacheKey@492726a5, value={"test":282}, version=1, hitCount=3, CreationTime = 1489534976848, LastAccessTime = 1489535172110 ]
    put at siteSettings: [ key = grails.plugin.cache.CustomCacheKeyGenerator$CacheKey@490f0efa, value={"test":229}, version=1, hitCount=0, CreationTime = 1489535172193, LastAccessTime = 1489535172193 ]

Analysis

1. on the first request where site=229, nothing has been cached. AS EXPECTED

2. on the second request where site=229, the entry keyed on 229 is cached. AS EXPECTED

3. on the first request where site=282, the entry keyed on 229 is cached, but the entry keyed on 282 is not cached. AS EXPECTED

4. on the second request where site=282, the entry keyed on 282 is cached, but the entry keyed on 229 is no longer cached. UNEXPECTED - expected both keys to be cached.

5. on the third request where site=229, the entry keyed on 282 is still cached, but the entry keyed on 229 is not cached. UNEXPECTED - expected both keys to be cached (subsequently, 282 is evicted, while 229 is put, which matches the observed behavior)

What am I doing wrong? Thanks for your help.

Answer 1

I'm sorry to say, but this whole thread turns out to be based on a mistake. The underlying problem was fixed by removing a line from a grails external config .properties file that appears to have masked the correct definition of grails.cache.config in Config.groovy. The external config was:

grails.cache.config.defaultCache.diskStore='java.io.tmpdir'

The suggested fix of adding an equals-sign to the grails.cache declaration is incorrect.

Answer 2

As I suspected, the configuration was at fault. In order for grails.plugin.cache.ConfigLoader to recognize that your grails.cache declaration in Config.groovy is a Closure, there must be an equals sign (=), like this:

Config.groovy:

// wrong
grails {
  cache {
    order = 2000
    enabled = true
    clearAtStartup = true
    shared = true
    ehcache {
      reloadable = false
    }
  }
}

// right
grails {
  cache = {
    order = 2000
    enabled = true
    clearAtStartup = true
    shared = true
    ehcache {
      reloadable = false
    }
  }
}

Unfortunately, this is not reflected in the documentation at http://grails-plugins.github.io/grails-cache-ehcache/guide/usage.html, which shows an example of this config element without the equals sign.

I discovered this after setting the grails.plugin.cache log-level to 'debug', when this logging output appeared:

DEBUG ehcache.EhcacheConfigLoader  - Not including configs from Config.groovy

Examining the source code for EhcacheConfigLoader showed that this error message results when the cache.config setting is not a Closure. Adding the equals sign to the config makes it a closure, and the cache configuration from Config.groovy is now loaded, which seems to fix the problem.