Thruster caching doesn't seem to be working

brenogazzola commented 2 months ago

Steps to reproduce

Open a terminal, type these commands to create a sample project

# Create a new project
rails new thruster-demo
cd thruster-demo

# Comment out the debug gem to get around a thruster bug
sed -i.bak '/gem "debug", platforms: %i\[ mri windows \]/s/^/#/' Gemfile && rm Gemfile.bak

# Tell puma to log asset requests
echo "quiet false" >> config/puma.rb

# Create a 10x10 red image to use as a placeholder asset
convert -size 10x10 xc:'#FF0000' public/red_image.png

# Add the sendfile header to development.rb
sed -i.bak '/config.assets.quiet = true/a\
config.action_dispatch.x_sendfile_header = "X-Sendfile"' config/environments/development.rb

# Install thruster and start it
gem install thruster
thrust rails s

Open a new terminal and start making requests for that asset (or use the browser with cache disabled):

curl http://localhost:80/red_image.png > /dev/null 2>&1
curl http://localhost:80/red_image.png > /dev/null 2>&1
curl http://localhost:80/red_image.png > /dev/null 2>&1

Expected behavior

Puma should log only the first asset request. Thruster should have the asset cached and handle the next two.
There should be a file called "red_image.png" in "storage/thruster"

Actual behavior

Puma will log every asset request, which means Thruster is not caching the asset and acting as a reverse proxy:

::1 - - [11/Apr/2024:11:13:47 -0300] "GET /red_image.png HTTP/1.1" 200 - 0.0011
{"time":"2024-04-11T11:13:47.513758-03:00","level":"INFO","msg":"Request","path":"/red_image.png","status":200,"dur":4,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":312,"resp_content_type":"image/png","remote_addr":"[::1]:65489","user_agent":"curl/8.4.0","cache":"miss","query":""}
::1 - - [11/Apr/2024:11:13:48 -0300] "GET /red_image.png HTTP/1.1" 200 - 0.0003
{"time":"2024-04-11T11:13:48.477155-03:00","level":"INFO","msg":"Request","path":"/red_image.png","status":200,"dur":0,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":312,"resp_content_type":"image/png","remote_addr":"[::1]:65491","user_agent":"curl/8.4.0","cache":"miss","query":""}
::1 - - [11/Apr/2024:11:13:48 -0300] "GET /red_image.png HTTP/1.1" 200 - 0.0003
{"time":"2024-04-11T11:13:48.907032-03:00","level":"INFO","msg":"Request","path":"/red_image.png","status":200,"dur":0,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":312,"resp_content_type":"image/png","remote_addr":"[::1]:65492","user_agent":"curl/8.4.0","cache":"miss","query":""}

The directory storage/thruster does not exist.

System configuration

Rails version: Rails 7.1.3.2 Ruby version: ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x86_64-darwin23]

jmonteiro commented 2 months ago

Thruster depends on the Cache-Control HTTP response header from the asset in order to cache it accordingly. Notice the following test section:

https://github.com/basecamp/thruster/blob/08e70b0bf094e7f749a366265abb852e6797aad4/internal/cacheable_response_test.go#L18-L26

These are Cache-Control headers that will yield a cached response on Thruster.

That means that you'll need to add config.public_file_server.headers = { "Cache-Control" => "public, max-age=#{2.days.to_i}" } to your config/environment/development.rb file in order to ensure Rails returns them to Thruster. (You could also touch tmp/caching-dev.txt but that'll also enable some Rails-side asset caching that we don't need/want here).

With this change, if you repeat your reproduction steps you'll have the following:

{"time":"2024-04-11T22:56:42.0000-03:00","level":"INFO","msg":"Request","path":"/red_image.png","status":200,"dur":5,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":312,"resp_content_type":"image/png","remote_addr":"[::1]:57156","user_agent":"curl/8.4.0","cache":"miss","query":""}
{"time":"2024-04-11T22:56:43.0000-03:00","level":"INFO","msg":"Request","path":"/red_image.png","status":200,"dur":0,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":312,"resp_content_type":"image/png","remote_addr":"[::1]:57158","user_agent":"curl/8.4.0","cache":"hit","query":""}
{"time":"2024-04-11T22:56:44.0000-03:00","level":"INFO","msg":"Request","path":"/red_image.png","status":200,"dur":0,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":312,"resp_content_type":"image/png","remote_addr":"[::1]:57161","user_agent":"curl/8.4.0","cache":"hit","query":""}

Notice that only the initial request has a "cache":"miss". The two follow ups have "cache":"hit". This is Thruster's log showing that the cache was found.

In the current version, assets are only cached in memory, not under the storage/thruster directory -- I believe only the SSL/TLS cert is stored on that directory.

kevinmcconnell commented 2 months ago

Thanks for answering this one, @jmonteiro!

Closing this as I believe Thruster is working as intended here. We will only cache responses that declare themselves to be cacheable, by way of the Cache-Control header.

basecamp / thruster