search

excid3 / ferrum_pdf

A PDF generator for Rails using Ferrum & headless Chrome
MIT License
197 stars 6 forks source link

Possibility to set Ferrum timeout to overcome code reloading issues in Development #5

Open borama opened 1 month ago

borama commented 1 month ago

Hello, thanks for this lovely gem! Coincidentally, I need to generate PDFs from HTML templates and I came up with the same approach - using Ferrum with Chromium browser - before I knew about this gem.

I hit one issue with this approach though: when using the default Puma configuration, I get deadlocks when I change some code, e.g. the HTML template, and refresh the page with the inline PDF, in Development environment. Everything works well until I make a change in the app code and Rails trigger a code reload during the refresh request.

After quite a few hours of debugging, I think that it is related to the Rails Load Interlock mechanism which locks all other threads during code reloading. And as the default configuration of Puma is to use 3 threads in a single worker in Development, this leads to a deadlock when Ferrum tries to load assets from localhost, such as CSS files from the template, leading to a Ferrum::TimeoutError in the end. The issue is very nicely explained in the documentation of Puma itself. I observed this behavior both on Rails 7.2 and Rail 8 beta.

So, to reproduce this, I can use the sample code from the README in a controller:

def show
  respond_to do |format|
    format.html
    format.pdf {
      pdf = render_pdf()
      send_data pdf, disposition: :inline, filename: "example.pdf"
    }
  end
end

then load the PDF version of the page (and the PDF shows inline without problems) ⟶ then I can make a change in the show template and refresh the page with the PDF ⟶ then I get the timeout after a few seconds.

In general this is not a big issue as one can tweak the HTML template and show it repeatedly as an HTML page before showing the final version in the PDF format. But still, FWIW, I came up with a simple solution after trying and failing several others:

The option to use permit_concurrent_loads, as suggested in the Puma doc, did not work for me, probably because we are dealing with not only "loading" but also "unloading" the Rails code. What worked well was to reconfigure Puma to use multiple workers each with a single thread instead, but I did not want to touch the defaults.

In the end, I rescued the TimeoutError and made the request to redirect to itself, like this:

def show
  respond_to do |format|
    format.html
    format.pdf {
      begin
        pdf = render_pdf()
        send_data pdf, disposition: :inline, filename: "example.pdf"
      rescue Ferrum::TimeoutError
        redirect_to(request.original_url)
      end
    }
  end
end

Now, when the deadlock occurs, Ferrum times out after (the default) 5 seconds and when Rails redirect to the same request, the Load Interlock is already released by then and the new request does not need to reload anything and Ferrum renders the PDF successfully. The logs for the scenario are shown below:

18:06:24 web.1  | Started GET "/notes/1.pdf" for 127.0.0.1 at 2024-09-30 18:06:24 +0200
18:06:24 web.1  | Processing by NotesController#show as PDF
18:06:24 web.1  |   Parameters: {"id"=>"1"}
18:06:24 web.1  |   Rendering layout layouts/application.html.erb
18:06:24 web.1  |   Rendering notes/show.html.erb within layouts/application
18:06:24 web.1  |   Rendered notes/show.html.erb within layouts/application (Duration: 0.2ms | GC: 0.0ms)
18:06:24 web.1  |   Rendered layout layouts/application.html.erb (Duration: 6.4ms | GC: 0.0ms)
18:06:24 web.1  | Started GET "/assets/tailwind-d3b98f27.css" for ::1 at 2024-09-30 18:06:24 +0200
18:06:29 web.1  | Redirected to http://localhost:3000/notes/1.pdf
18:06:29 web.1  | Completed 302 Found in 5103ms (ActiveRecord: 0.0ms (0 queries, 0 cached) | GC: 0.0ms)
18:06:29 web.1  |
18:06:29 web.1  |
18:06:29 web.1  | Started GET "/assets/inter-font-1d90a608.css" for ::1 at 2024-09-30 18:06:29 +0200
18:06:29 web.1  | Started GET "/notes/1.pdf" for 127.0.0.1 at 2024-09-30 18:06:29 +0200
18:06:29 web.1  | Processing by NotesController#show as PDF
18:06:29 web.1  |   Parameters: {"id"=>"1"}
18:06:29 web.1  |   Rendering layout layouts/application.html.erb
18:06:29 web.1  |   Rendering notes/show.html.erb within layouts/application
18:06:29 web.1  |   Rendered notes/show.html.erb within layouts/application (Duration: 0.4ms | GC: 0.0ms)
18:06:29 web.1  |   Rendered layout layouts/application.html.erb (Duration: 5.1ms | GC: 0.0ms)
18:06:29 web.1  | Started GET "/assets/tailwind-d3b98f27.css" for ::1 at 2024-09-30 18:06:29 +0200
...
18:06:29 web.1  | Started GET "/assets/turbo.min-e867e79e.js" for ::1 at 2024-09-30 18:06:29 +0200
18:06:29 web.1  |   Rendering text template
18:06:29 web.1  |   Rendered text template (Duration: 0.5ms | GC: 0.0ms)
18:06:29 web.1  | Sent data example.pdf (1.5ms)
18:06:29 web.1  | Completed 200 OK in 631ms (Views: 1.3ms | ActiveRecord: 0.0ms (0 queries, 0 cached) | GC: 13.4ms)

Now, back to my original suggestion: it would be nice to be able to set the Ferrum timeout, for example to 1s in Development, to reduce the time one has to wait before the redirect is run. I can't see a way to set Ferrum options in the current gem code. Or, perhaps, this redirect might be baked in the gem itself…?

I can try to prepare a PR if you find any of this reasonable. Thanks!

excid3 commented 1 month ago

You can use FerrumPdf.browser(options) to set them, but it could probably use some refactoring.

Do you have steps to reproduce in the test/dummy app?

borama commented 1 month ago

Oh, I missed that option, thanks. OK, I will try to prepare some reproducible case in the test/dummy app.

borama commented 1 month ago

OK so when I boot up the dummy app:

test/dummy$ bin/rails s

go to home page ⟶ click "PDF" ⟶ the invoice comes up:

obrazek

now when I change anything in the code, such as the address in the pdfs/show.html.erb template and reload the page with the PDF open, I get a timeout after 5 seconds:

obrazek

obrazek

When I reload the same page again, all Rails code is fine again and the updated PDF shows correctly:

obrazek

borama commented 1 month ago

FYI, I successfully updated our code with a short custom Ferrum timeout on Development env and it works very well, thank you, I will close this now.

mlitwiniuk commented 1 month ago

@borama As I've just run into this issue (and most likely others will as well), would you care to share your solution?

borama commented 1 month ago

Sure! My workaround is the following code:

class ThingsController < ApplicationController
  def show
    respond_to do |format|
      format.html

      format.pdf do
        code_reloading = Rails.application.config.enable_reloading

        begin
          FerrumPdf.browser(timeout: 1) if code_reloading

          pdf = render_pdf(layout: "pdf_page", pdf_options: { format: :A4, print_background: true })
          send_data(pdf, type: "application/pdf", disposition: "inline")
        rescue Ferrum::TimeoutError
          redirect_to(request.original_url) if code_reloading
        end
      end
    end
  end
end

In a controller, this applies a 1s timeout and a redirect to self when "code reloading" is enabled, i.e. when the config.enable_reloading option is set in a Rails environment (as it is by default in config/development.rb).

On production, this should do nothing special and just render the PDF with a default timeout and no redirects, because the enable_reloading config option is usually disabled on production.

So far it seems to work very well.

excid3 commented 1 month ago

There's probably something we can do on our end for Rails development. I'm not sure exactly what.

excid3 commented 1 month ago

Both threads are sleeping in the debug lock middleware output:

Thread 0 [0x44ac sleep]  No lock (yielded share)
  Waiting in start_exclusive to "unload"
  may be pre-empted for: "load", "unload"
  blocked by: 1

/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:107:in `sleep'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:107:in `wait'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:107:in `wait_for_cond'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:107:in `wait'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:115:in `wait_while'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/concurrency/share_lock.rb:220:in `wait_for'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/concurrency/share_lock.rb:83:in `block (2 levels) in start_exclusive'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/concurrency/share_lock.rb:82:in `block in start_exclusive'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:201:in `synchronize'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/3.3.0/monitor.rb:201:in `mon_synchronize'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/concurrency/share_lock.rb:77:in `start_exclusive'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/dependencies/interlock.rb:21:in `start_unloading'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/reloader.rb:108:in `require_unload_lock!'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/reloader.rb:127:in `class_unload!'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/application/finisher.rb:217:in `block (2 levels) in <module:Finisher>'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:407:in `instance_exec'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:407:in `block in make_lambda'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:179:in `block in call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:668:in `block (2 levels) in default_terminator'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:667:in `catch'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:667:in `block in default_terminator'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:180:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:559:in `block in invoke_before'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:559:in `each'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:559:in `invoke_before'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:109:in `run_callbacks'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/execution_wrapper.rb:128:in `run'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/execution_wrapper.rb:124:in `run!'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/reloader.rb:122:in `run!'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/execution_wrapper.rb:77:in `block in run!'
<internal:kernel>:90:in `tap'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/execution_wrapper.rb:74:in `run!'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/reloader.rb:64:in `run!'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:31:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/show_exceptions.rb:32:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/rack/logger.rb:41:in `call_app'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/rack/logger.rb:29:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/remote_ip.rb:96:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/request_id.rb:33:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/method_override.rb:28:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/runtime.rb:24:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/executor.rb:16:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/static.rb:27:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/sendfile.rb:114:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/debug_locks.rb:45:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/engine.rb:535:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/configuration.rb:272:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/request.rb:100:in `block in handle_request'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/thread_pool.rb:378:in `with_force_shutdown'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/request.rb:99:in `handle_request'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/server.rb:464:in `process_client'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/server.rb:245:in `block in run'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/thread_pool.rb:155:in `block in spawn_thread'

---

Thread 1 [0x44fc sleep]  Sharing
  blocking: 0

/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/ferrum-0.15/lib/ferrum/network.rb:68:in `sleep'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/ferrum-0.15/lib/ferrum/network.rb:68:in `wait_for_idle'
/Users/chris/code/ferrum_pdf/lib/ferrum_pdf.rb:39:in `block in render'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/ferrum-0.15/lib/ferrum/browser.rb:163:in `create_page'
/Users/chris/code/ferrum_pdf/lib/ferrum_pdf.rb:36:in `render'
/Users/chris/code/ferrum_pdf/lib/ferrum_pdf.rb:24:in `render_pdf'
/Users/chris/code/ferrum_pdf/lib/ferrum_pdf/controller.rb:8:in `render_pdf'
/Users/chris/code/ferrum_pdf/test/dummy/app/controllers/pdfs_controller.rb:9:in `block (2 levels) in show'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/mime_responds.rb:224:in `respond_to'
/Users/chris/code/ferrum_pdf/test/dummy/app/controllers/pdfs_controller.rb:6:in `show'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/basic_implicit_render.rb:8:in `send_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/abstract_controller/base.rb:226:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/rendering.rb:193:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/abstract_controller/callbacks.rb:261:in `block in process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actiontext-7.2.1/lib/action_text/rendering.rb:25:in `with_renderer'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actiontext-7.2.1/lib/action_text/engine.rb:71:in `block (4 levels) in <class:Engine>'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:130:in `instance_exec'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:141:in `run_callbacks'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/abstract_controller/callbacks.rb:260:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/rescue.rb:27:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/instrumentation.rb:77:in `block in process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/notifications.rb:210:in `block in instrument'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/notifications.rb:210:in `instrument'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/instrumentation.rb:76:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activerecord-7.2.1/lib/active_record/railties/controller_runtime.rb:39:in `process_action'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/abstract_controller/base.rb:163:in `process'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionview-7.2.1/lib/action_view/rendering.rb:40:in `process'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_controller/metal.rb:335:in `dispatch'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/routing/route_set.rb:67:in `dispatch'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/routing/route_set.rb:50:in `serve'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/journey/router.rb:53:in `block in serve'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/journey/router.rb:133:in `block in find_routes'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/journey/router.rb:126:in `each'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/journey/router.rb:126:in `find_routes'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/journey/router.rb:34:in `serve'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/routing/route_set.rb:896:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/tempfile_reaper.rb:20:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/etag.rb:29:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/conditional_get.rb:31:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/head.rb:15:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/http/permissions_policy.rb:38:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/http/content_security_policy.rb:36:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-session-2.0.0/lib/rack/session/abstract/id.rb:272:in `context'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-session-2.0.0/lib/rack/session/abstract/id.rb:266:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/cookies.rb:704:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/callbacks.rb:31:in `block in call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/callbacks.rb:101:in `run_callbacks'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/callbacks.rb:30:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/executor.rb:16:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:31:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/show_exceptions.rb:32:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/rack/logger.rb:41:in `call_app'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/rack/logger.rb:29:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/remote_ip.rb:96:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/request_id.rb:33:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/method_override.rb:28:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/runtime.rb:24:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/activesupport-7.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/executor.rb:16:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/static.rb:27:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/rack-3.1.7/lib/rack/sendfile.rb:114:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/actionpack-7.2.1/lib/action_dispatch/middleware/debug_locks.rb:45:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/railties-7.2.1/lib/rails/engine.rb:535:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/configuration.rb:272:in `call'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/request.rb:100:in `block in handle_request'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/thread_pool.rb:378:in `with_force_shutdown'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/request.rb:99:in `handle_request'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/server.rb:464:in `process_client'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/server.rb:245:in `block in run'
/Users/chris/.local/share/mise/installs/ruby/3.3.2/lib/ruby/gems/3.3.0/gems/puma-6.4.3/lib/puma/thread_pool.rb:155:in `block in spawn_thread'
borama commented 1 month ago

Yes, that was my observation, too.

My initial guess was that the permit_concurrent_loads should work, the documentation seems to cover this scenario. The problem with this method though is that it permits running only threads with the lock compatibility set to :load but we are dealing with reloading classes here which involves both :unload and :load lock compatibility settings, as can be seen in the Interlock methods for unloading classes. I think that these methods are used when Rails is reloading code in Development.

To check this hypothesis, I wrapped the PDF generation in a permit_concurrent_loads block:

pdf = nil

ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
  pdf = render_pdf
end

send_data(pdf, type: "application/pdf", disposition: "inline")

and temporarily added the :unload thread lock compatibility setting to the ones allowed by permit_concurrent_loads in the Rails Interlock:

module ActiveSupport
  module Dependencies
    class Interlock

      def permit_concurrent_loads(&block)
        @lock.yield_shares(compatible: [:load, :unload], &block)
      end

    end
  end
end

And indeed, reloading PDFs started to magically work again!

Now that I think of it, perhaps a permit_concurrent_reloads is missing in the Rails Interlock…? But all of this is way above my standard Rails knowledge, so… :sweat_smile: