[SOLVED] Caffeine cache in Play Framework doesn't return cached responses

I'm using Caffeine cache implementation with my java Play Framework job to cache outgoing http requests, and I see that in spite of the fact that the cache is up and running, my service still hit the external server every time instead of returning the value from the cache. And I see that the key logged in the logs is always the same.

So I see freshnessLifetime is not set, so it might mean that the cache expires immediately. but I still don't know how to set it in the config

I have not changed my java code and I cannot find any examples if I need to do that, or I'm only supposed to have a config for cache working for all outgoing requests.

I would appreciate any help with this

My build.sbt contains:

libraryDependencies += ws
libraryDependencies += caffeine

My reference.conf contains:

# Configuration settings for JSR 107 Cache for Play WS.
play.ws.cache {
  enabled = true
  heuristics.enabled = false
  name = "play-ws-cache"
}

My application.conf contains:

# source https://github.com/ben-manes/caffeine/blob/master/jcache/src/main/resources/reference.conf
caffeine.jcache {
  # A named cache is configured by nesting a new definition under the caffeine.jcache namespace. The
  # per-cache configuration is overlaid on top of the default configuration.
  play-ws-cache {
    read-through {
      # If enabled, the entry is loaded automatically on a cache miss
      enabled = true
    }
    # The eviction policy for automatically removing entries from the cache
    policy {
      # The expiration threshold before lazily evicting an entry. This single threshold is reset on
      # every operation where a duration is specified. As expected by the specification, if an entry
      # expires but is not accessed and no resource constraints force eviction, then the expired
      # entry remains in place.
      lazy-expiration {
        # The duration before a read of an entry is considered expired. If set to 0 then the entry
        # is considered immediately expired. May be a time duration, null to indicate no change, or
        # "eternal" to indicate no expiration.
        access = 5m
      }
      # The expiration thresholds before eagerly evicting an entry. These settings correspond to the
      # expiration supported natively by Caffeine where expired entries are collected during
      # maintenance operations.
      eager-expiration {
        # Specifies that each entry should be automatically removed from the cache once a fixed
        # duration has elapsed after the entry's creation, the most recent replacement of its value,
        # or its last read. Access time is reset by all cache read and write operation. This setting
        # cannot be combined with the variable configuration.
        after-access = 5m
      }
      # The maximum bounding of the cache based upon its logical size
      maximum {
        # The maximum number of entries that can be held by the cache. This setting cannot be
        # combined with the weight configuration.
        size = 10000
      }
    }
  }
}

I see in the logs this:

[debug] - restclient.BaseRestClient - Executing GET with url http://localhost:9001/entities/v2/867386732 [trace] - p.a.l.w.a.c.CachingAsyncHttpClient - execute: request = Request(GET http://localhost:9001/entities/v2/867386732), handler = AsyncHandler(play.libs.ws.ahc.StandaloneAhcWSClient$ResponseAsyncCompletionHandler@65b0b233), future = null [debug] - p.a.libs.ws.ahc.cache.AhcHttpCache - get: key = GET http://localhost:9001/entities/v2/867386732 [debug] - p.a.l.w.a.c.CachingAsyncHttpClient - execute GET http://localhost:9001/entities/v2/867386732: results = List(ResponseEntry(CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:08 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1),GET,Map(),Some(2020-10-02T10:44:08.760450-07:00[America/Los_Angeles]))) [trace] - c.t.c.ResponseSelectionCalculator - findMatchingResponse: request = CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), responses = List(StoredResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)),GET,Map())) [debug] - p.a.l.w.a.c.CachingAsyncHttpClient - execute GET http://localhost:9001/entities/v2/867386732: selected from cache: ResponseEntry(CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:08 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1),GET,Map(),Some(2020-10-02T10:44:08.760450-07:00[America/Los_Angeles])) [trace] - c.t.c.CurrentAgeCalculator - calculateCurrentAge(headers: TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)), now: 2020-10-01T17:44:38.690992Z[GMT], requestTime: 2020-10-01T17:44:38.690274Z[GMT], responseTime: 2020-10-01T17:44:38.690981Z[GMT]) [trace] - c.t.c.CurrentAgeCalculator

calculateCurrentAge: currentAge = PT30S [debug] - c.t.c.ResponseServingCalculator - serveResponse: response found for 'GET http://localhost:9001/entities/v2/867386732', age = 30 [trace] - c.t.c.ResponseServingCalculator - noCacheFound: request = CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), response = StoredResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)),GET,Map()) [trace] - c.t.c.ResponseServingCalculator - isCachedResponseFresh: request = CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), response = StoredResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)),GET,Map()) [trace] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: [debug] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: freshnessLifetime = None [debug] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: result = PT0S [debug] - c.t.c.ResponseServingCalculator - isCachedResponseFresh: freshnessLifetime = PT0S, currentAge = PT30S [debug] - c.t.c.ResponseServingCalculator - isCachedResponseFresh: freshnessLifetime = PT0S, currentAge = PT30S [trace] - c.t.c.ResponseServingCalculator - isStaleResponseProhibited: request = CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), response = StoredResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)),GET,Map()) [trace] - c.t.c.ResponseServingCalculator - isStaleResponseAllowed: PT30S, request = CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), response = StoredResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)),GET,Map()) [debug] - c.t.c.ResponseServingCalculator - isStaleResponseAllowed: stale response not allowed [trace] - c.t.c.ResponseServingCalculator - canServeStaleAndRevalidate: response = StoredResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:08 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)),GET,Map()) [trace] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: [debug] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: freshnessLifetime = None [debug] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: result = PT0S [trace] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: [debug] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: freshnessLifetime = None [debug] - c.t.c.FreshnessCalculator - calculateFreshnessLifetime: result = PT0S [debug] - p.a.l.w.a.c.CachingAsyncHttpClient - serveResponse GET http://localhost:9001/entities/v2/867386732: Response is stale, and stale response is not allowed -- revalidate with staleIfError = false [trace] - p.a.l.w.a.c.CachingAsyncHttpClient - buildValidationRequest: Request(GET http://localhost:9001/entities/v2/867386732), response = CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:08 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1) [debug] - p.s.a.o.a.n.r.NettyRequestSender - Using pooled Channel '[id: 0x1fac35f7, L:/127.0.0.1:49899 - R:localhost/127.0.0.1:9001]' for 'GET' to 'http://localhost:9001/entities/v2/867386732' [debug] - p.s.a.o.a.n.r.NettyRequestSender - Using open Channel [id: 0x1fac35f7, L:/127.0.0.1:49899 - R:localhost/127.0.0.1:9001] for GET '/entities/v2/867386732' [trace] - p.s.a.i.n.h.logging.LoggingHandler

[id: 0x1fac35f7, L:/127.0.0.1:49899 - R:localhost/127.0.0.1:9001] WRITE: 107B

[debug] - p.s.a.o.a.netty.handler.HttpHandler -

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE) GET /entities/v2/867386732 HTTP/1.1 host: localhost:9001 accept: / user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1) HTTP/1.1 200 OK Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin X-Frame-Options: DENY X-XSS-Protection: 1; mode=block X-Content-Type-Options: nosniff X-Permitted-Cross-Domain-Policies: master-only Date: Thu, 01 Oct 2020 17:44:38 GMT Content-Type: application/json Content-Length: 2144

[debug] - p.s.a.o.a.n.channel.ChannelManager - Adding key: http://localhost:9001 for channel [id: 0x1fac35f7, L:/127.0.0.1:49899

R:localhost/127.0.0.1:9001] [trace] - p.a.l.w.a.cache.AsyncCachingHandler - onCompleted: this = CacheAsyncHandler(key = GET http://localhost:9001/entities/v2/867386732, requestTime = 2020-10-01T17:44:38.692247Z[GMT], builder = play.api.libs.ws.ahc.cache.CacheableResponseBuilder@492a840f, asyncHandler = AsyncHandler(play.libs.ws.ahc.StandaloneAhcWSClient$ResponseAsyncCompletionHandler@65b0b233)}) [debug] - p.a.l.w.a.cache.AsyncCachingHandler - onCompleted: response = CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:38 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1) [trace] - p.a.libs.ws.ahc.cache.AhcHttpCache - invalidate: request = Request(GET http://localhost:9001/entities/v2/867386732), response = CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:38 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1) [debug] - p.a.l.w.a.cache.AsyncCachingHandler - processFullResponse: fullResponse = CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:38 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1) [trace] - c.t.c.ResponseCachingCalculator - isCacheable: request: CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), response = OriginResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:38 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only))) [trace] - c.t.c.ResponseCachingCalculator - responseIsCacheable: response = OriginResponse(http://localhost:9001/entities/v2/867386732,200,TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:38 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only))) [trace] - c.t.c.ResponseCachingCalculator - isCacheable: result = DoCacheResponse(Response status code 200 is cacheable by default) [debug] - p.a.l.w.a.cache.AsyncCachingHandler - isCacheable: DO CACHE, because Response status code 200 is cacheable by default [debug] - p.a.libs.ws.ahc.cache.AhcHttpCache - cacheResponse: response = CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:38 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1) [debug] - p.a.libs.ws.ahc.cache.AhcHttpCache - cacheResponse: strippedResponse = CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:38 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1) [trace] - c.t.c.SecondaryKeyCalculator - calculate: request = CacheRequest(http://localhost:9001/entities/v2/867386732,GET,TreeMap()), responseHeaders = TreeMap(Date -> List(Thu, 01 Oct 2020 17:44:38 GMT), Content-Type -> List(application/json), Content-Length -> List(2144), Referrer-Policy -> List(origin-when-cross-origin, strict-origin-when-cross-origin), X-Frame-Options -> List(DENY), X-XSS-Protection -> List(1; mode=block), X-Content-Type-Options -> List(nosniff), X-Permitted-Cross-Domain-Policies -> List(master-only)) [debug] - p.a.libs.ws.ahc.cache.AhcHttpCache - put: key = GET http://localhost:9001/entities/v2/867386732, entry = ResponseEntry(CacheableResponse(status = CacheableHttpResponseStatus(code = 200, text = OK), headers = DefaultHttpHeaders[Referrer-Policy: origin-when-cross-origin, strict-origin-when-cross-origin, X-Frame-Options: DENY, X-XSS-Protection: 1; mode=block, X-Content-Type-Options: nosniff, X-Permitted-Cross-Domain-Policies: master-only, Date: Thu, 01 Oct 2020 17:44:38 GMT, Content-Type: application/json, Content-Length: 2144], bodyParts size = 1),GET,Map(),Some(2020-10-02T10:44:38.771750-07:00[America/Los_Angeles])) [debug] - restclient.BaseRestClient - Response status [200] for url [http://localhost:9001/entities/v2/867386732] [trace] - p.s.a.i.n.h.logging.LoggingHandler - [id: 0x1fac35f7, L:/127.0.0.1:49899 - R:localhost/127.0.0.1:9001] READ COMPLETE [trace]

p.a.l.w.ahc.cache.CacheableResponse - getResponseBody: