Inconsistent content returned from CF cache and can't seem to purge

Hi,

I have a path on my site https://wolstenhol.me/api/recently-played which is a cached proxy to https://eoh55mp2n2usj4p.m.pipedream.net. The URLs will return the last song I listened to on Spotify, or an empty JSON object if I haven’t listened to anything recently.

When I hit the uncached Pipedream URL with CURL I consistently get the results I expect:

❯ curl https://eoh55mp2n2usj4p.m.pipedream.net
{"playedAt":"2022-02-26T18:40:17.179Z","name":"Changes - Calibre Remix","artistList":"Danny Byrd, Calibre","trackUrl":"https://open.spotify.com/track/3HXMBcIvyNOA2vwuYTNhcS"}%
❯ curl https://eoh55mp2n2usj4p.m.pipedream.net
{"playedAt":"2022-02-26T18:40:17.179Z","name":"Changes - Calibre Remix","artistList":"Danny Byrd, Calibre","trackUrl":"https://open.spotify.com/track/3HXMBcIvyNOA2vwuYTNhcS"}%
❯ curl https://eoh55mp2n2usj4p.m.pipedream.net
{"playedAt":"2022-02-26T18:40:17.179Z","name":"Changes - Calibre Remix","artistList":"Danny Byrd, Calibre","trackUrl":"https://open.spotify.com/track/3HXMBcIvyNOA2vwuYTNhcS"}%

But when I hit the cached wolstenhol.me URL, I get different data in the response even with just a second or two in between the requests:

❯ curl https://wolstenhol.me/api/recently-played
{"playedAt":"2022-02-25T18:49:57.851Z","name":"Everybody But You","artistList":"State Champs, Ben Barlow","trackUrl":"https://open.spotify.com/track/0OjhULGHagMRAQNjJQlesU"}%
❯ curl https://wolstenhol.me/api/recently-played
{"playedAt":"2022-02-25T15:22:54.568Z","name":"Sundown","simplifiedArtists":"Duke Boara","trackUrl":"https://open.spotify.com/track/1wk4sL0DMj0A46MktCZIW5"}%
❯ curl https://wolstenhol.me/api/recently-played
{}%
❯ curl https://wolstenhol.me/api/recently-played
{"playedAt":"2022-02-26T18:40:17.179Z","name":"Changes - Calibre Remix","artistList":"Danny Byrd, Calibre","trackUrl":"https://open.spotify.com/track/3HXMBcIvyNOA2vwuYTNhcS"}%
❯ curl https://wolstenhol.me/api/recently-played
{"playedAt":"2022-02-25T15:22:54.568Z","name":"Sundown","simplifiedArtists":"Duke Boara","trackUrl":"https://open.spotify.com/track/1wk4sL0DMj0A46MktCZIW5"}%
❯ curl https://wolstenhol.me/api/recently-played
{"playedAt":"2022-02-26T18:40:17.179Z","name":"Changes - Calibre Remix","artistList":"Danny Byrd, Calibre","trackUrl":"https://open.spotify.com/track/3HXMBcIvyNOA2vwuYTNhcS"}%

Fine, I thought, I’ll clear the cache by URL – but that didn’t seem to fix the issue. Neither did the nuclear option of the ‘Purge cache’ button in the admin web UI, and neither did using the zones/:identifier/purge_cache endpoint either.

When I look at the caches being returned I can see a collection of HIT and MISSes, and I can also see a temporary cache-control: max-age=30099999 header that I added to the source at one point but subsequently removed. Has this response with the high max-age value somehow got ‘stuck’ in Cloudflare? I thought it would have been removed when I purged?

Here are some headers from requests all made seconds apart:

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:16:57 GMT
content-type: application/json; charset=utf-8
content-length: 173
access-control-allow-origin: *
cache-control: max-age=30099999
x-nf-request-id: 01FWVQDXG26M2V3R5F58JSPYGP
x-powered-by: Express
cf-cache-status: MISS
last-modified: Sat, 26 Feb 2022 19:16:57 GMT
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=s2KBN84xa%2FAHyGuVLoQKP8EVdLDQeRTLhjWhv%2BmmVdJeYAvWWzeBBUGr55OCeR35GUY3xFblRRu%2B5Gs0tlCn03r42Kc0ODpUnQqPb4y6%2FlrxfYi8fW6tVjFbEJ9RzFg9"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b82c269bae618-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:17:00 GMT
content-type: application/json; charset=utf-8
content-length: 174
access-control-allow-origin: *
cache-control: public,max-age=0,s-maxage=3600,must-revalidate
x-nf-request-id: 01FWVQE05ZZJWB83P3ATE5Q60D
x-powered-by: Express
cf-cache-status: MISS
last-modified: Sat, 26 Feb 2022 19:17:00 GMT
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=gVhqyrZQDr4FNk38IXvoEoQGrfX9qUTexYW1TxDbX9EnsJeZCWS8vgZCsfCNQAK7ttkgE6xO33SzCzjDOxsr6OHA%2B7B3onAAVfh%2B6OhKivbH3CGWmQR0axKttWL%2BfDwd"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b82d3fc5b8880-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:17:03 GMT
content-type: application/json; charset=utf-8
content-length: 174
access-control-allow-origin: *
age: 3
cache-control: public,max-age=0,s-maxage=3600,must-revalidate
x-nf-request-id: 01FWVQE05ZZJWB83P3ATE5Q60D
x-powered-by: Express
cf-cache-status: HIT
last-modified: Sat, 26 Feb 2022 19:17:00 GMT
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=rpBI%2Fn%2FY4%2BxtzcZfbfkiusP5AM7BZXBZknRHfksliMX6%2F4SEfwjOoV7Y9YB1mkXEFYKcTujSfDCEnqRlHdRY%2B8DsSW3sJ%2FimP92dw568HklXVmFdXa5QU2cr2EoFaPuA"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b82e90a9171e6-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:17:04 GMT
content-type: application/json; charset=utf-8
content-length: 174
access-control-allow-origin: *
age: 4
cache-control: public,max-age=0,s-maxage=3600,must-revalidate
x-nf-request-id: 01FWVQE05ZZJWB83P3ATE5Q60D
x-powered-by: Express
cf-cache-status: HIT
last-modified: Sat, 26 Feb 2022 19:17:00 GMT
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=knohUuMmb42h6uJ%2FwyqLoJ993v9VWYV0qzVnhxnouJQiSbnCtPfCJ9Oz0XueXWfZN0vS2mvvN7Umbk2vLC6aqxm5fUeTnIhs%2B9qCxeUBl10bBQB6Jo%2BsJt%2F4QpXJIkvy"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b82f1aedb71cf-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:17:05 GMT
content-type: application/json; charset=utf-8
content-length: 174
access-control-allow-origin: *
age: 5
cache-control: public,max-age=0,s-maxage=3600,must-revalidate
x-nf-request-id: 01FWVQE05ZZJWB83P3ATE5Q60D
x-powered-by: Express
cf-cache-status: HIT
last-modified: Sat, 26 Feb 2022 19:17:00 GMT
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=j2iQRnMV9L18mzDvOeKrkk%2FX7Y3jR6gYBUzAZYZvPs%2BRVJHriU8Nf0DztB%2B43G%2FlrhBv1fvp%2FYEea6uAlh%2FAazR0nXMBIOq5e%2Bd1SDpUWdlG8cFshTpkCJBuIAKJcNtg"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b82f6e9408861-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:17:06 GMT
content-type: application/json; charset=utf-8
content-length: 173
access-control-allow-origin: *
cache-control: public,max-age=0,s-maxage=3600,must-revalidate
etag: "ad-ka0EPZhrtnHYEPgYadrGaL/ipaU"
x-nf-request-id: 01FWVQE6C0G3ZEKSCDAPQVQ9T1
x-powered-by: Express
cf-cache-status: MISS
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=qrCosWGgQfvebFByziweUz5wk9uNK81HESmU8jot%2Fotojt%2BaieJTk5DlbFvaie1LciaekD5w9iCyaCURRHujWcqVoBtJdM9vJiB%2F%2BGy3I0ZuH6U1F2N4aP5QQOiaf17U"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b82fbbd2e889d-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

❯ curl -I https://wolstenhol.me/api/recently-played
HTTP/2 200
date: Sat, 26 Feb 2022 19:17:07 GMT
content-type: application/json; charset=utf-8
content-length: 173
access-control-allow-origin: *
age: 10
cache-control: max-age=30099999
x-nf-request-id: 01FWVQDXG26M2V3R5F58JSPYGP
x-powered-by: Express
cf-cache-status: HIT
last-modified: Sat, 26 Feb 2022 19:16:57 GMT
accept-ranges: bytes
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=HtXThJ6oTjgobjzCnS9n8%2BcnLsjuJnvKITtBt8m%2BfKy3jaeN0o1LkGmZE%2Fnb%2Fnn1KWjDb49UNPc%2FLR7Hi3UvSJ7VlWPqTgxIrfeg7LoKxPIs3h79x2RXicxPJqceKGZ%2F"}],"group":"cf-nel","max_age":604800}
nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
strict-transport-security: max-age=2592000
x-content-type-options: nosniff
server: cloudflare
cf-ray: 6e3b83006bd3407e-LHR
alt-svc: h3=":443"; ma=86400, h3-29=":443"; ma=86400

I am on the free plan, with these page rules in place:

In the headers you can see how I’ve been playing around with cache-control headers on the source – my current plan is to use something like public,max-age=0,s-maxage=3600,must-revalidate to prevent browser caching but ask Cloudflare to hang onto the file for a while.

Hi,

Intermittent issues are very hard to troubleshoot, but I believe the issue is at the origin.

I’ve run the curl command quite a few times and always got the expected header (except that now it seems you’ve lowered s-maxage to 300).

From the results you posted, the first two are MISSes. A MISS indicates that the content and headers were fetched from the origin, except for the headers CF adds in the response, most of which begin with cf-.

These two MISSes each came with a different cache-control header, the first one having the max-age=30099999. the second carrying the correct cache-control header.

If your diff this last MISS result against subsequent HIT ones (served by CF Cache), you’ll notice that the x-nf-request-id always match.

What’s a bit intriguing is the last MISS, which is followed by a HIT with the max-age=30099999. That must have been the result of another request going to the origin between the MISS and the HIT. I say that because the origin identifier x-nf-request-id does not match here.

So in all likelihood another request (from another device or someone else) hit the origin and caused that last request to be fetched from cache.

Why would Cloudflare return a MISS after only a second or two is not clear, though you need to bear in mind that the time your set as s-maxage (or max-age) is only the maximum time you are instructing CF to hold in cache, but an unfrequently visited resource may be evicted from CF’s cache at any time (even frequently resources, for that matter).

Why would your origin at times return the wrong cache-control header is something you need to investigate at the origin.

1 Like

Interesting, thank you @cbrandt

I am using Netlify to handle proxying the https://eoh55mp2n2usj4p.m.pipedream.net URL (the endpoint that provides the cache-control headers) to make it available on https://wolstenhol.me/api/recently-played (to avoid adding the cost of a DNS lookup). I wonder if Netlify’s caching is hanging onto a response with the max-age=30099999 – I’ll investigate.

I imagine that one Netlify edge node has cached the old response with the high max-age.

Thanks again, I wasn’t aware of how the x-nf-request-id header could be used for debugging like this :+1:

1 Like

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.