Bug with caching long expires signed s3 urls

[aspark21]

I just noticed on one of our test servers the site logo wasn't loading, which is weird since all the data comes from s3. By opening image in a new tab I saw this error returned by S3. (We are using signed urls not the local server caching on the test servers).

<Error>
<Code>AccessDenied</Code>
<Message>Request has expired</Message>
<X-Amz-Expires>604740</X-Amz-Expires>
<Expires>2021-06-03T11:10:47Z</Expires>
<ServerTime>2021-06-28T15:34:52Z</ServerTime>
<RequestId></RequestId>
<HostId></HostId>
</Error>

The link to that image was cached somehow.

Just updated Moodle which did a cache purge & resolved this.

Need to think about this more but writing up before I forget.

Question is wether theme is being naughty (Adaptable) or if when using signedurls we have to have to rely on caches being purged relatively regularly to avoid that happening.

Seems weird this would be cached at all though.

[brendanheywood]

Objectfs looks at the caching headers send by moodle to create the signature, so it should Just Work(tm) even if the theme is setting the wrong headers. Might also be something like a cdn in the middle adding headers?

[aspark21]

By caching I meant the basic cache/localcache. We don't have any Varnish type caching in front of this Moodle, no CDN. And no MUC either.

[brendanheywood]

It would be good to see a bunch of raw details, like the original pluginfile url and its headers, and the signed url it redirected to and its headers. Also which settings you have on and off: eg it sounds like this is s3 signing not cloudfront signing?

[aspark21]

Yes S3 signing. I'm thinking the url for the site logo, images in blocks etc are coming through into the html and then being cached by those basic caches.

We're purging caches regularly at the moment because new plugins & upcoming release so It'll take a few weeks to re-create the conditions I think. Will let you know

[balabhadra]

@aspark21 Did you get any solution on this? I'm having the exact same issue.

[balabhadra]

@brendanheywood This definitely looks like some sort of caching issue. Once we purge moodle cache, the logo and theme images reappear. But they get accessdenied errors again in 2-3 days.

[brendanheywood]

There is still no real details to go on here, can you please put in an example of the original moodle plugin file url, and a full dump of all the http headers it serves alongside the redirect to the signed url and all the signed urls headers too, both when it works and then later on again when it no longer works. Ideally if its just a theme file on a public site then there should not be a need to redact anything, but remove the domains if that is an issue.

Also if the theme is open source please link to the pluginfile function in lib.php which serves the image (if it is not using the core theme file serving urls)

[balabhadra]

@brendanheywood Thank you for the response. Please find the details below:

Plugin file url: https://xyz.net.au/pluginfile.php/1/theme_xyz/logo/1627976318/logo.png

This url redirects to s3 url which looks like: https://xyz.s3.ap-southeast-2.amazonaws.com/14/de/14de64d8f719b5bbfa1701ce2a8492e68c0932bc? (Query string params below)

* response-content-disposition: inline; filename="logo.png"
* response-content-type: image/png
* X-Amz-Content-Sha256: UNSIGNED-PAYLOAD
* X-Amz-Algorithm: AWS4-HMAC-SHA256
* X-Amz-Credential: placeholder
* X-Amz-Date: 20210803T073841Z
* X-Amz-SignedHeaders: host
* X-Amz-Expires: 604740
* X-Amz-Signature: placeholder

Request headers with theme images not working.

#Request headers I get from chrome developer tools for pluginfile url

:authority: xyz.net.au
:method: GET
:path: /pluginfile.php/1/theme_xyz/logo/1627976318/logo.png
:scheme: https
accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cache-control: no-cache
cookie: MoodleSession=52359f0d27422d47ba4bd6b48b72e0da; MOODLEID1_=%25AA4k%25D2%2513s
pragma: no-cache
referer: https://xyz.net.au/admin/category.php?category=tool_objectfs
sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
sec-ch-ua-mobile: ?0
sec-fetch-dest: image
sec-fetch-mode: no-cors
sec-fetch-site: same-origin
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

#Request headers I get from chrome developer tools for redirected s3 url

Accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Cache-Control: no-cache
Connection: keep-alive
Host: xyz.s3.ap-southeast-2.amazonaws.com
Pragma: no-cache
Referer: https://xyz.net.au/
sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
sec-ch-ua-mobile: ?0
Sec-Fetch-Dest: image
Sec-Fetch-Mode: no-cors
Sec-Fetch-Site: cross-site
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

We're using a custom theme but the pluginfile function looks mostly standard

function theme_xyz_pluginfile($course, $cm, $context, $filearea, $args, $forcedownload, array $options = array()) {
    $theme = theme_config::load(‘xyz’);

    $available_filearea = ['logo', 'backgroundimage', 'bannerimage', 'aboutus_image'];

    if ($context->contextlevel == CONTEXT_SYSTEM && (in_array($filearea, $available_filearea) || strpos($filearea, 'categoryimg') !== false) ) {
        // By default, theme files must be cache-able by both browsers and proxies.
        if (!array_key_exists('cacheability', $options)) {
            $options['cacheability'] = 'public';
        }
        return $theme->setting_file_serve($filearea, $args, $forcedownload, $options);
    } else {
        send_file_not_found();
    }
}

[balabhadra]

@brendanheywood - Just added a random param to the pluginfile url and the image opens normally (probably bypassed caching through the random param)

#Request headers I get from chrome developer tools for pluginfile url

:authority: xyz.net.au
:method: GET
:path: /pluginfile.php/1/theme_xyz/logo/1627976318/logo.png?test=1
:scheme: https
accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
accept-encoding: gzip, deflate, br
accept-language: en-US,en;q=0.9
cookie: MoodleSession=097480cae5ad21790e072ad901d445f0
sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
sec-ch-ua-mobile: ?0
sec-fetch-dest: document
sec-fetch-mode: navigate
sec-fetch-site: none
sec-fetch-user: ?1
upgrade-insecure-requests: 1
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

#Request headers I get from chrome developer tools for redirected s3 url

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Connection: keep-alive
Host: xyz.s3.ap-southeast-2.amazonaws.com
sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
sec-ch-ua-mobile: ?0
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: none
Sec-Fetch-User: ?1
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

[brendanheywood]

thanks @balabhadra can you repeat that but include both the http request headers and the http response headers? In particular the things I'm looking for is the caching header in the pluginfile response which serves the redirect. I suspect there is something wrong with it and its being cached for too long

Whatever the redirect url has for its caching must be shorter than the caching on the url it redirects to. So lets say the redirect itself is cached for 1 day, but the signed url is only valid for an hour then that's gonne break in an hour.

* X-Amz-Expires: 604740

The logic for all this is here:

https://github.com/catalyst/moodle-tool_objectfs/blob/master/classes/local/store/s3/client.php#L564-L589

[balabhadra]

Thanks @brendanheywood. Just seems that moodle by default caches theme images and style sheets for a long duration. I'm referring to the Theme designer mode setting, screenshot below. Turning this on does make the site very slow.

So not sure what would be appropriate solution.

[brendanheywood]

@balabhadra yes there are many resources like js and css which are considered as immutable and the default moodle setup will serve those urls with a Cache-control and Expires headers. If you have a varnish or CDN layer in front of moodle then it will cache then and those requests will not end up at the php layer after that. Then there are the 'middle' types of requests which are not 'immutable, public' and which have a short term Expires header and these are the ones which can be served by a signed url.

All of this is working just fine with the Cloudfront signing, but I suspect there is either an edge case bug with the s3 signing (which we don't use in prod so its not as battle tested as cloudfront) - or there is a difference in the s3 api which means it can't signatures older than some fixed limit.

I think the fundamental issue here is that the pluginfile url is being served with caching headers which are X days long, and it is redirecting to the signed url which has an expry if Y, and X < Y. Which is why I need to see the response headers for both urls to compare.

If s3 signed urls cannot support longer expires then when it generates the signed url it needs to mutate the expires headers on the plugin file to shorten the expires on the redirect before sending it.

[balabhadra]

@brendanheywood Thank you. Sorry for late response but were you able to identify the issue? Please let me know if you still require any information.

[brendanheywood]

I still haven't seen the info I asked for in: https://github.com/catalyst/moodle-tool_objectfs/issues/422#issuecomment-906893252

I need both sets of request + response headers for the plugin file and for the final signed url. It is very likely an issue with the s3 signing code, but as we don't use that it will not be high on our list to fix unless you want to sponsor it (we use cloudfront signing)

[balabhadra]

@brendanheywood Please find all the details:

Pluginfile (Working)

Request Headers

* :authority: xyz.net.au
* :method: GET
* :path: /pluginfile.php/1/theme_xyz/logo/1630559617/logo.png
* :scheme: https
* accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
* accept-encoding: gzip, deflate, br
* accept-language: en-US,en;q=0.9
* cache-control: no-cache
* cookie: MOODLEID1_=%25AA4k%25D2%2513s; MoodleSession=ed693da0a443e0d0ec6136d2c522281d
* pragma: no-cache
* referer: https://xyz.net.au/
* sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
* sec-ch-ua-mobile: ?0
* sec-fetch-dest: image
* sec-fetch-mode: no-cors
* sec-fetch-site: same-origin
* user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

Response Headers

* cache-control: public, max-age=5184000, no-transform
* content-disposition: inline; filename="logo.png"
* content-language: en
* content-security-policy: upgrade-insecure-requests
* content-type: image/png
* date: Sun, 05 Sep 2021 04:12:51 GMT
* etag: "14de64d8f719b5bbfa1701ce2a8492e68c0932bc"
* expires: Mon, 01 Nov 2021 05:13:41 GMT
* host-header: 8441280b0c35cbc1147f8ba998a563a7
* last-modified: Wed, 08 Apr 2020 13:05:54 GMT
* location: https://xyz.s3.ap-southeast-2.amazonaws.com/14/de/14de64d8f719b5bbfa1701ce2a8492e68c0932bc?[query_strings]
* pragma
* server: nginx
* x-httpd: 1
* x-proxy-cache: HIT

S3 (Working)

Request Headers

* Accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
* Accept-Encoding: gzip, deflate, br
* Accept-Language: en-US,en;q=0.9
* Cache-Control: no-cache
* Connection: keep-alive
* Host: xyz.s3.ap-southeast-2.amazonaws.com
* Pragma: no-cache
* Referer: https://xyz.net.au/
* sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
* sec-ch-ua-mobile: ?0
* Sec-Fetch-Dest: image
* Sec-Fetch-Mode: no-cors
* Sec-Fetch-Site: cross-site
* User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

Response Headers

* Accept-Ranges: bytes
* Content-Disposition: inline; filename="logo.png"
* Content-Length: 12402
* Content-Type: image/png
* Date: Sun, 26 Sep 2021 12:50:20 GMT
* ETag: "58f2fa0ca0ae60d37e1f2de8f45f7796"
* Last-Modified: Wed, 19 May 2021 10:08:08 GMT
* Server: AmazonS3
* x-amz-id-2: Ogr6Hk9srFHsRvuBkkWEq4im1zgcoLc3ME3+GuXvf6HVEyPsIWQialF1TLFOXRVlBIHVMk4svVA=
* x-amz-request-id: VQ2801KY0TBA1SHF

Pluginfile (Not working)

Request Headers

* :authority: xyz.net.au
* :method: GET
* :path: /pluginfile.php/1/theme_xyz/logo/1631083258/logo.png
* :scheme: https
* accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
* accept-encoding: gzip, deflate, br
* accept-language: en-US,en;q=0.9
* cache-control: no-cache
* cookie: MOODLEID1_=%25AA4k%25D2%2513s; MoodleSession=f4be47aaa4b8e033727302dd56f8c0c2
* pragma: no-cache
* referer: https://xyz.net.au/
* sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
* sec-ch-ua-mobile: ?0
* sec-fetch-dest: image
* sec-fetch-mode: no-cors
* sec-fetch-site: same-origin
* user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

Response Headers

* cache-control: public, max-age=5184000, no-transform
* content-disposition: inline; filename="logo.png"
* content-language: en
* content-security-policy: upgrade-insecure-requests
* content-type: image/png
* date: Sun, 19 Sep 2021 03:41:27 GMT
* etag: "14de64d8f719b5bbfa1701ce2a8492e68c0932bc"
* expires: Sun, 07 Nov 2021 06:41:10 GMT
* host-header: 8441280b0c35cbc1147f8ba998a563a7
* last-modified: Wed, 08 Apr 2020 13:05:54 GMT
* location: https://xyz.s3.ap-southeast-2.amazonaws.com/14/de/14de64d8f719b5bbfa1701ce2a8492e68c0932bc?[query_strings]
* pragma
* server: nginx
* x-httpd: 1
* x-proxy-cache: HIT

S3 (Not working)

Request Headers

* Accept: image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8
* Accept-Encoding: gzip, deflate, br
* Accept-Language: en-US,en;q=0.9
* Cache-Control: no-cache
* Connection: keep-alive
* Host: xyz.s3.ap-southeast-2.amazonaws.com
* Pragma: no-cache
* Referer: https://xyz.net.au/
* sec-ch-ua: "Chromium";v="92", " Not A;Brand";v="99", "Google Chrome";v="92"
* sec-ch-ua-mobile: ?0
* Sec-Fetch-Dest: image
* Sec-Fetch-Mode: no-cors
* Sec-Fetch-Site: cross-site
* User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36

Response Headers

* Content-Type: application/xml
* Date: Sun, 19 Sep 2021 03:41:29 GMT
* Server: AmazonS3
* Transfer-Encoding: chunked
* x-amz-id-2: ZzJg8DH+ix7Ai+rREv8UMKH+EhN1y5WpNfF99jMeEhb3yw6RbGrRDL39S3TRLQbbxWku2+/VoDI=
* x-amz-request-id: B6JFWBN7EXZ8Z54W

[brendanheywood]

Your request is on the Sun, 19 Sep and you posted that message on the 26 Sep which is one week later which is very suspicious time period. We've hit something similar to this before and handled it here already:

https://github.com/catalyst/moodle-tool_objectfs/blob/a43206024972ef1e61413e620971e90808844922/classes/local/store/s3/client.php#L579-L584

https://aws.amazon.com/premiumsupport/knowledge-center/presigned-url-s3-bucket-expiration/

So I'm fairly sure the problem is the pluginfile needs to have its expires header overwritten with the new 'max 1 week' expires which is used in the signed url. The signed url is expiring, but nginx has cached the old url and is sending the old one instead of php sending the new one.

You should be able to test that theory by waiting for the conditions to be met, and then carefully clearing the nginx cache and nothing else and seeing if it works.

To fix it is something like:

1) Change the contract for generate_presigned_url so that it not only gets passed in the request headers but can also pass out headers which need to be changed (ie expires). This could be as a 3rd arg to an array pointer, or change the return value to an object. (generate_presigned_url could just set the headers itself but I dislike it having side effects and this might cause other issues down the track)

2) When the signed url is used grab the response header back out, and then set them to overwrite the ones already set by pluginfile, here:

https://github.com/catalyst/moodle-tool_objectfs/blob/master/classes/local/store/object_file_system.php#L807

3) The original response headers might have the expires set in a bunch of different ways, such as Expires and cache-control max age, and other older headers. So perhaps instead of generate_presigned_url returning a set of headers it only returns an explicit timestamp, and then redirect_to_presigned_url sets or removes all of these potential headers in one place.

Pull requests welcome!

[aspark21]

I encountered it again but following your logic that this could be cached by Nginx I had a look at the Puppet code for that server and it doesn't have the disk cache disabled - https://httpd.apache.org/docs/2.4/mod/mod_cache_disk.html We have had a lot of the signs of trouble we would expect when that's enabled but had believed this to have been fully switched off across our estate after the trouble it has given us in the past.

So will have to see if it crops up again after that is switched off properly on that box.

This reminds me of https://tracker.moodle.org/browse/MDL-73127 which was being discussed before the break (our original hell with mod_cache_disk) - telling those caching layers to stop keeping hold of things. I unfortunately didn't manage to capture the request/response headers before invalidating it this time.

[sammarshallou]

We hit the same problem here. The issue is that we send some image files using moodle send_stored_file function with expiry set to 1 year. The code in objectfs to limit the presigned url length works correctly, limiting it to 1 week, but after 1 week, the image disappears because the browser has cached the redirect for 1 year, then it gets to the S3 URL which just ouputs an error including 'Request has expired'. There are 2 parts to the problem:

1) The redirect sent by Moodle needs to have its expiry changed (as per Brendan's comment above) if it is longer than 1 week.

2) Why is the browser trying to reload the image from S3 anyway - is there no way to have it indefinitely cached, same as the intent from original Moodle? If S3 sent the 1 year expiry header then (a) this problem would almost go away (browser doesn't re-request the redirect, also doesn't re-request the resulting image, so it still works), and (b) it would be more efficient... I had a quick look and various StackExchange code suggests there may be some option called ResponseCacheControl or response-cache-control or something like that which maybe you can use when getting the presigned URL, but the docs for this are terrible and I can't find it.

(In total this is a bit unfortunate because if we fix point 1 then it means even if we also fix point 2, nothing can ever be cached in browser for longer than 1 week, so it does make it less efficient. But more efficient than at present when it won't be cached in browser beyond current session at all.)

We are seeing this both with custom code and with user profile images. Here is an example of the latter on one of our servers which I think is publicly available (note - behaviour subject to change if I happen to patch a fix):

https://learn1.open.ac.uk/pluginfile.php/93991/user/icon/osep/f1?rev=33847418

That URL sends a 303 redirect. Selected response headers from that 303:

... expires: Fri, 03 Mar 2023 15:28:49 GMT ... location: https://learn1live-s3bucket.s3.eu-west-2.amazonaws.com/3d/33/3d33d723341f472f393b9111604552a848c1582d?response-content-disposition=inline%3B%20filename%3D%22f1.png%22&response-content-type=image%2Fpng&X-Amz-Content-Sha256=UNSIGNED-PAYLOAD&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIA4HQROLVIVP5SYXXC%2F20220303%2Feu-west-2%2Fs3%2Faws4_request&X-Amz-Date=20220303T152849Z&X-Amz-SignedHeaders=host&X-Amz-Expires=604740&X-Amz-Signature=_REDACTED_ ...

As you can see, the expiry in AWS is set to 604740 (one week) which means that URL will only work for a week, whereas the 303 redirect (that generated the url) is set to expire only after a year. So if you request the url, then wait a week, then request it again, it should pull the redirect from cache and redirect to the expired S3 URL and therefore stop working.

I might have a look at this because we probably at least need a temp fix here...