User:Puxlit/MediaWiki API Cache Modes — dev

Motivation

action=parse (anon-public-user-private mode) won't pass through cache-control of public with maxage for anon users
useful cache headers is desirable for reducing number of requests by AddRailModule

Overview

entry point: https://github.com/Wikia/app/blob/release-807.001/api.php
cache modes: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L246-L288
generation of cache headers: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L410-L489
other points of interest:
- https://github.com/Wikia/app/blob/release-807.001/includes/OutputPage.php

Empirical Testing

permutations: config ⨯ {t + 0s, t + 10s}
- config = candidates ⨯ {without smaxage/maxage, with smaxage = maxage = 600} ⨯ {anon, logged in}

curl:

curl --verbose --compressed --globoff
     -H 'fastly-debug: 1'
     -H 'fastly-force-shield: 1'
     -H 'cookie: […]'
     'https://dev.wikia.com/api.php?format=json&smaxage=[…]&maxage=[…]&requestid=[…]&[…]'

use requestid param for controlled cache busting between configs

candidates:
- for public, action=query&meta=siteinfo:
  - cache mode is defined: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQuerySiteinfo.php#L521
  - cache mode is passed through: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQuery.php#L291-L292
- for private, action=query&meta=userinfo:
  - cache mode is defined: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQueryBase.php#L62 ← https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQueryUserInfo.php#L32
  - cache mode is passed through: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQuery.php#L293-L294
- for anon-public-user-private, action=query&meta=allmessages&amcustomised=modified (without amlang):
  - cache mode is defined: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQueryAllmessages.php#L190-L192
  - cache mode is passed through: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQuery.php#L287-L289

Assumptions

we're dealing with modules that don't explicitly override smaxage/maxage via setCacheMaxAge (https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L239-L244), like https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiQueryRevisions.php#L581
we're not dealing with private wikis: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L278-L284
$wgUseXVO and $wgVaryOnXFP are false:
intermediate caches between origin and client may rewrite headers (which may account for difference between expectation and reality)

Results

#!/bin/sh -eux

run_config() (
    [ $# -ge 2 ] || exit 1
    readonly __rc_name="$1" __rc_query_string_extra="$2"; shift 2
    [ ! -e "${__rc_name}" ] || exit 2

    __rc_request_id="$(printf '%s' "${__rc_name}" | openssl dgst -binary -sha1 | xxd -p | cut -c -16)"
    __rc_t00_outfile="${__rc_name}-t00.txt"
    __rc_t10_outfile="${__rc_name}-t10.txt"
    readonly __rc_request_id __rc_t00_outfile __rc_t10_outfile
    [ ! -e "${__rc_t00_outfile}" ] || exit 3
    [ ! -e "${__rc_t10_outfile}" ] || exit 4

    ( curl --silent --verbose --compressed --globoff -H 'fastly-debug: 1' -H 'fastly-force-shield: 1' "$@" "https://dev.wikia.com/api.php?format=json&requestid=${__rc_request_id}${__rc_query_string_extra}" >"${__rc_t00_outfile}" 2>&1 ) &&
    sleep 10 &&
    ( curl --silent --verbose --compressed --globoff -H 'fastly-debug: 1' -H 'fastly-force-shield: 1' "$@" "https://dev.wikia.com/api.php?format=json&requestid=${__rc_request_id}${__rc_query_string_extra}" >"${__rc_t10_outfile}" 2>&1 ) &&
    sleep 5
)

nonce=''              # set to something unique per run
anon_cookies=''       # set to that of an anon wikia session
logged_in_cookies=''  # set to that of a logged in wikia session
readonly nonce anon_cookies logged_in_cookies

run_config "${nonce}-00-public-without_maxages-anon"                                               '&action=query&meta=siteinfo'                          -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-01-public-without_maxages-logged_in"                                          '&action=query&meta=siteinfo'                          -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-02-public-with_maxages-anon"                           '&smaxage=600&maxage=600&action=query&meta=siteinfo'                          -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-03-public-with_maxages-logged_in"                      '&smaxage=600&maxage=600&action=query&meta=siteinfo'                          -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-04-private-without_maxages-anon"                                              '&action=query&meta=userinfo'                          -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-05-private-without_maxages-logged_in"                                         '&action=query&meta=userinfo'                          -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-06-private-with_maxages-anon"                          '&smaxage=600&maxage=600&action=query&meta=userinfo'                          -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-07-private-with_maxages-logged_in"                     '&smaxage=600&maxage=600&action=query&meta=userinfo'                          -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-08-anon_public_user_private-without_maxages-anon"                             '&action=query&meta=allmessages&amcustomised=modified' -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-09-anon_public_user_private-without_maxages-logged_in"                        '&action=query&meta=allmessages&amcustomised=modified' -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-10-anon_public_user_private-with_maxages-anon"         '&smaxage=600&maxage=600&action=query&meta=allmessages&amcustomised=modified' -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-11-anon_public_user_private-with_maxages-logged_in"    '&smaxage=600&maxage=600&action=query&meta=allmessages&amcustomised=modified' -H "cookie: ${logged_in_cookies}"

for public:
- expectation:
  - cache-control header is:
    - private if neither smaxage nor maxage are set: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L451-L465
    - s-maxage=[…], max-age=[…], public otherwise: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L467 and https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L474-L488
  - expires header is:
    - absent if neither smaxage nor maxage are set: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L451-L465
    - approx. request timestamp + minimum of smaxage and maxage otherwise: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L469-L472
  - vary header is Accept-Encoding,Cookie: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L446 and https://github.com/Wikia/app/blob/release-807.001/includes/OutputPage.php#L230-L233
- reality:
  - age header is:
    - for cases where we wouldn't expect caching:
      - set four times to 0 for the initial request
      - (set once to) 0 for the subsequent request
      - this is possibly related to this, since we see accept-ranges: bytes duplicated five times for the initial request, and four times for the subsequent request
      - occasionally, this header is missing altogether for the subsequent request (and we see accept-ranges: bytes duplicated three times instead of four)
    - for cases where we'd expect caching:
      - (set once to) 0 for the initial request
      - (set once to) approx. 10 for the subsequent request
      - interestingly, we also don't see any duplication of accept-ranges: bytes
  - cache-control header is as expected
  - date header is probably set by the edge cache
  - expires header is missing for cases where we'd expect it to be set (which should be fine since cache-control's smaxage/maxage takes precedence)
  - fastly-debug-digest header is unique per config as expected (since we'd vary on query string and cookies)
  - surrogate-key header is as expected (wiki-7931 wiki-7931-mediawiki)
  - vary header is as expected
  - x-served-by/x-cache/x-cache-hits is ap-s[…], cache-wk-sjc[…]-WIKIA, cache-syd[…]-SYD/ORIGIN, MISS, MISS/ORIGIN, 0, 0 (and …/ORIGIN, MISS, HIT/ORIGIN, 0, 1 for cases where we'd expect a cached response) as expected
  - x-cacheable header is:
    - YES for cases where we'd expect caching to be allowed
    - NO:Got Session if we're logged in
    - NO:Cache-Control=private otherwise
for private:
- expectation:
  - cache-control header is private (with no smaxage/maxage): https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L421-L424
  - expires header is absent: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L421-L424
  - vary header is absent: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L421-L424
- reality:
  - age header is:
    - set four times to 0 for the initial request
    - (set once to) 0 for the subsequent request
    - this is possibly related to this, since we see accept-ranges: bytes duplicated five times for the initial request, and four times for the subsequent request
    - occasionally, this header is missing altogether for the subsequent request (and we see accept-ranges: bytes duplicated three times instead of four)
  - cache-control header is as expected
  - date header is probably set by the edge cache
  - expires header is as expected
  - fastly-debug-digest header is unique per config as expected (since we'd vary on query string and cookies)
  - surrogate-key header is as expected (wiki-7931 wiki-7931-mediawiki)
  - vary header is Accept-Encoding (which'd be reasonable for an intermediate cache to set)
  - x-served-by/x-cache/x-cache-hits is ap-s[…], cache-wk-sjc[…]-WIKIA, cache-syd[…]-SYD/ORIGIN, MISS, MISS/ORIGIN, 0, 0 as expected
  - x-cacheable header is:
    - NO:Got Session if we're logged in
    - NO:Cache-Control=private otherwise
for anon-public-user-private:
- expectation:
  - cache-control header is:
    - private if we're anon(?): https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L437-L441
    - same as public cache mode otherwise: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L442
  - expires header is:
    - absent if we're anon(?): https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L437-L441
    - same as public cache mode otherwise: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L442
  - vary header is Accept-Encoding,Cookie: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L426-L428 and https://github.com/Wikia/app/blob/release-807.001/includes/OutputPage.php#L230-L233
- reality:
  - age header is:
    - for cases where we wouldn't expect caching:
      - set four times to 0 for the initial request
      - (set once to) 0 for the subsequent request
      - this is possibly related to this, since we see accept-ranges: bytes duplicated five times for the initial request, and four times for the subsequent request
      - occasionally, this header is missing altogether for the subsequent request (and we see accept-ranges: bytes duplicated three times instead of four)
    - for cases where we'd expect caching:
      - (set once to) 0 for the initial request
      - (set once to) approx. 10 for the subsequent request
      - interestingly, we also don't see any duplication of accept-ranges: bytes
  - cache-control header is as expected
  - date header is probably set by the edge cache
  - expires header is missing for cases where we'd expect it to be set (which should be fine since cache-control's smaxage/maxage takes precedence)
  - fastly-debug-digest header is unique per config as expected (since we'd vary on query string and cookies)
  - surrogate-key header is as expected (wiki-7931 wiki-7931-mediawiki)
  - vary header is as expected
  - x-served-by/x-cache/x-cache-hits is ap-s[…], cache-wk-sjc[…]-WIKIA, cache-syd[…]-SYD/ORIGIN, MISS, MISS/ORIGIN, 0, 0 (and …/ORIGIN, MISS, HIT/ORIGIN, 0, 1 for cases where we'd expect a cached response) as expected
  - x-cacheable header is:
    - YES for cases where we'd expect caching to be allowed
    - NO:Got Session if we're logged in
    - NO:Cache-Control=private otherwise

Isolating the Weirdness

run_config "${nonce}-00-without_maxages-anon"                             '&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp='                             -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-01-without_maxages-logged_in"                        '&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp='                             -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-02-with_maxages-anon"         '&smaxage=600&maxage=600&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp='                             -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-03-with_maxages-logged_in"    '&smaxage=600&maxage=600&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp='                             -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-04-without_maxages-anon"                             '&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=API'                   -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-05-without_maxages-logged_in"                        '&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=API'                   -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-06-with_maxages-anon"         '&smaxage=600&maxage=600&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=API'                   -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-07-with_maxages-logged_in"    '&smaxage=600&maxage=600&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=API'                   -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-08-without_maxages-anon"                             '&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=Special:RecentChanges' -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-09-without_maxages-logged_in"                        '&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=Special:RecentChanges' -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-10-with_maxages-anon"         '&smaxage=600&maxage=600&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=Special:RecentChanges' -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-11-with_maxages-logged_in"    '&smaxage=600&maxage=600&action=parse&text={{FULLPAGENAME}}@{{CURRENTTIMESTAMP}}&prop=text&uselang=en&disablepp=&title=Special:RecentChanges' -H "cookie: ${logged_in_cookies}"

configuration above derived by permuting inclusion/exclusion of the parameters {title, prop, uselang, disablepp}; text is always included
- without title, the response headers that we're interested in are all as expected
- with title, most of the response headers that we're interested in are as expected, but:
  - the cache-control header is always private, s-maxage=0, max-age=0, must-revalidate 🤔
  - the fastly-debug-digest header is the same across configs, despite variations in query string, cookies, and response body 🤔🤔🤔
  - this applies even when we're setting title to the default value of API, which suggests the effect is occurring outside of the parse API module

run_config "${nonce}-00-without_maxages-anon"                             '&action=query&meta=siteinfo'             -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-01-without_maxages-logged_in"                        '&action=query&meta=siteinfo'             -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-02-with_maxages-anon"         '&smaxage=600&maxage=600&action=query&meta=siteinfo'             -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-03-with_maxages-logged_in"    '&smaxage=600&maxage=600&action=query&meta=siteinfo'             -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-04-without_maxages-anon"                             '&action=query&meta=siteinfo&title=dummy' -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-05-without_maxages-logged_in"                        '&action=query&meta=siteinfo&title=dummy' -H "cookie: ${logged_in_cookies}" &&
run_config "${nonce}-06-with_maxages-anon"         '&smaxage=600&maxage=600&action=query&meta=siteinfo&title=dummy' -H "cookie: ${anon_cookies}"      &&
run_config "${nonce}-07-with_maxages-logged_in"    '&smaxage=600&maxage=600&action=query&meta=siteinfo&title=dummy' -H "cookie: ${logged_in_cookies}"

same behaviour observed
normally, the cache-control header appears just after the x-backend-response-time/x-trace-id/x-span-id headers: https://github.com/Wikia/app/blob/release-807.001/includes/api/ApiMain.php#L415 and https://github.com/Wikia/app/blob/release-807.001/includes/wikia/Wikia.php#L1618-L1621
headers emitted in that vicinity (like x-cache and x-cache-hits: https://github.com/Wikia/app/blob/release-807.001/includes/wikia/Wikia.php#L1625-L1626) that would be modified by cache servers wind up near the bottom of the list of response headers
the pathological cache-control header happens to appear towards the bottom of the list of response headers
given we're getting a cached response when we're supposed to (age greater than zero, x-cache-hits: ORIGIN, 0, 1, x-cacheable: YES, timestamps baked into the response body are appropriately dated), it seems reasonable to assume that an intermediate cache is rewriting cache-control based in part on the presence of the title GET param

--- 02-with_maxages-anon-t00.cleaned_response_headers.txt
+++ 06-with_maxages-anon-t00.cleaned_response_headers.txt
@@ -1,27 +1,27 @@
 < HTTP/2 200 
 < server: Apache
 < x-content-type-options: nosniff
 < surrogate-key: wiki-7931 wiki-7931-mediawiki
 < content-security-policy-report-only: default-src https: 'self' data: blob:; script-src https: 'self' data: 'unsafe-inline' 'unsafe-eval' blob:; style-src https: 'self' 'unsafe-inline' blob:; report-uri https://services.wikia.com/csp-logger/csp/app
 < x-frame-options: DENY
 < content-disposition: inline; filename="api-result.json"
 < x-backend-response-time: […]
 < x-trace-id: […]
 < x-span-id: […]
-< cache-control: s-maxage=600, max-age=600, public
 < content-encoding: gzip
 < content-type: application/json; charset=utf-8
 < x-datacenter: SJC
 < x-cacheable: YES
 < accept-ranges: bytes
 < date: […]
 < age: 0
 < fastly-debug-path: (D cache-syd[…]-SYD […]) (D cache-wk-sjc[…]-WIKIA […])
 < fastly-debug-ttl: (M cache-syd[…]-SYD - - 0) (M cache-wk-sjc[…]-WIKIA - - 0)
 < fastly-debug-digest: […]
 < x-served-by: ap-s[…], cache-wk-sjc[…]-WIKIA, cache-syd[…]-SYD
 < x-cache: ORIGIN, MISS, MISS
 < x-cache-hits: ORIGIN, 0, 0
 < x-timer: […]
 < vary: Accept-Encoding,Cookie
+< cache-control: private, s-maxage=0, max-age=0, must-revalidate
 < content-length: […]

Official Response

reported as #436237: Unexpected Cache-Control headers when performing MediaWiki API requests that contain a title param
explicit clarification was that:
- the witnessed cache header rewrites for api.php responses are expected behaviour (and not encroachment of rules meant for index.php); and
- indiscriminate cache header rewrites based on the presence of the title query param (irrespective of whether that param is even valid for the target API module(s)) is expected behaviour