Wrap application code in Rails executor to prevent autoloading problems

[jorgemanrubia]

Broadcasting happens from a thread and involves a SolidCable::Message model that is auto-reloaded by Rails in development. This can result in race conditions where the ActionCable thread tries to access the model class but it can't resolve it.

https://guides.rubyonrails.org/threading_and_code_execution.html

[npezza93]

Nice! Thanks.

[npezza93]

3.0.3 is out and includes this fix @jorgemanrubia

[jorgemanrubia]

Wonderful, thanks @npezza93 🙏

[miharekar]

Since upgrading to 3.0.3 I get an unresponsive Rails server in development the first time when I make any change in any template. Reading the changelog, I'm guessing this here is the issue 😅

These are the last logs I see:

09:02:42 web.1         | 2024-12-06 09:02:42.736528 I [20524:puma srv tp 001] (173.8ms) CafesController -- Completed #edit -- {:controller=>"CafesController", :action=>"edit", :params=>{"id"=>"6026"}, :format=>"HTML", :method=>"GET", :path=>"/cafes/6026/edit", :status=>200, :view_runtime=>4.06, :db_runtime=>117.46, :queries_count=>62, :cached_queries_count=>30, :allocations=>160546, :status_message=>"OK"}
09:02:42 web.1         | 2024-12-06 09:02:42.742299 I [20524:ActionCable-worker-2] ActionCable -- Finished "/cable" [WebSocket] for ::1 at 2024-12-06 09:02:42 +0100
09:02:42 web.1         | 2024-12-06 09:02:42.742383 I [20524:ActionCable-worker-2] ActionCable -- Turbo::StreamsChannel stopped streaming from Z2lkOi8vZWN0L1VzZXIvMQ:notifications
09:02:42 web.1         | 2024-12-06 09:02:42.742418 I [20524:ActionCable-worker-2] ActionCable -- Turbo::StreamsChannel stopped streaming from notifications
09:02:42 web.1         | 2024-12-06 09:02:42.828979 D [20524:puma srv tp 002] Rack -- Started -- {:method=>"GET", :path=>"/cable", :ip=>"::1"}
09:02:42 web.1         | 2024-12-06 09:02:42.841414 I [20524:puma srv tp 002] ActionCable -- Started GET "/cable" [WebSocket] for ::1 at 2024-12-06 09:02:42 +0100
09:02:42 web.1         | 2024-12-06 09:02:42.841432 I [20524:puma srv tp 002] ActionCable -- Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
09:02:42 web.1         | 2024-12-06 09:02:42.860601 D [20524:worker-2] ActionCable -- Turbo::StreamsChannel is transmitting the subscription confirmation
09:02:42 web.1         | 2024-12-06 09:02:42.860706 I [20524:worker-2] ActionCable -- Turbo::StreamsChannel is streaming from Z2lkOi8vZWN0L1VzZXIvMQ:notifications
09:02:42 web.1         | 2024-12-06 09:02:42.860718 D [20524:worker-1] ActionCable -- Turbo::StreamsChannel is transmitting the subscription confirmation
09:02:42 web.1         | 2024-12-06 09:02:42.860752 I [20524:worker-1] ActionCable -- Turbo::StreamsChannel is streaming from notifications
09:02:48 css.1         |
09:02:48 css.1         | Rebuilding...
09:02:48 css.1         |
09:02:48 css.1         | Done in 177ms.
^C09:02:56 system        | SIGINT received, starting shutdown
09:02:56 system        | sending SIGTERM to all processes
09:02:56 solid_queue.1 | exited with code 0
09:02:56 web.1         | - Gracefully stopping, waiting for requests to finish
09:02:57 css.1         | exited with code 0
^C^C09:03:01 system        | sending SIGKILL to all processes

I tried removing tailwind from Procfile.dev, but then there's just nothing in the logs, and the request is pending as before on the browser side.

[jorgemanrubia]

Hmm I can't reproduce that on my side 🤔. Could you share your development.rb, Rails version, Procfileand cable.yml to see if I manage to reproduce @miharekar? Fine if you prefer to send those by email if you don't want to post them here ([email protected]). I don't understand how this block could happen at a first glance.

@npezza93 Feel free to revert and release a new version while we troubleshoot. I have mixed feelings about waiting to see if we get more reports here, since a hanging dev server is pretty bad. Sorry about the trouble!

[jorgemanrubia]

Also, which db are you using @miharekar?

[miharekar]

I'm on rails 8.0.0, using PG for main db and sqlite for cable.

Here are all the files, I'm more or less sticking with defaults.

require "active_support/core_ext/integer/time"

Rails.application.configure do
  # Settings specified here will take precedence over those in config/application.rb.

  config.hosts << "ect.test"

  # Make code changes take effect immediately without server restart.
  config.enable_reloading = true

  # Do not eager load code on boot.
  config.eager_load = false

  # Show full error reports.
  config.consider_all_requests_local = true

  # Enable server timing.
  config.server_timing = true

  # Enable/disable Action Controller caching. By default Action Controller caching is disabled.
  # Run rails dev:cache to toggle Action Controller caching.
  if Rails.root.join("tmp/caching-dev.txt").exist?
    config.action_controller.perform_caching = true
    config.action_controller.enable_fragment_cache_logging = true
    config.cache_store = :solid_cache_store
    config.public_file_server.headers = {"cache-control" => "public, max-age=#{2.days.to_i}"}
  else
    config.action_controller.perform_caching = false
    config.cache_store = :null_store
  end

  # Store uploaded files on the local file system (see config/storage.yml for options).
  config.active_storage.service = :cloudflare

  # Don't care if the mailer can't send.
  config.action_mailer.raise_delivery_errors = true

  # Make template changes take effect immediately.
  config.action_mailer.perform_caching = false
  config.action_mailer.delivery_method = :letter_opener
  config.action_mailer.perform_deliveries = true

  # Set localhost to be used by links generated in mailer templates.
  config.action_mailer.default_url_options = {host: "localhost", port: 3000}
  config.action_mailer.deliver_later_queue_name = :mailers

  # Print deprecation notices to the Rails logger.
  config.active_support.deprecation = :log

  # Raise an error on page load if there are pending migrations.
  config.active_record.migration_error = :page_load

  # Highlight code that triggered database queries in logs.
  config.active_record.verbose_query_logs = true

  # Append comments with runtime information tags to SQL queries in logs.
  config.active_record.query_log_tags_enabled = true

  # Highlight code that enqueued background job in logs.
  config.active_job.verbose_enqueue_logs = true

  # Raises error for missing translations.
  # config.i18n.raise_on_missing_translations = true

  # Annotate rendered view with file names.
  config.action_view.annotate_rendered_view_with_filenames = true

  # Uncomment if you wish to allow Action Cable access from any origin.
  # config.action_cable.disable_request_forgery_protection = true

  # Raise error when a before_action's only/except options reference missing actions.
  config.action_controller.raise_on_missing_callback_actions = true

  # Apply autocorrection by RuboCop to files generated by `bin/rails generate`.
  config.generators.apply_rubocop_autocorrect_after_generate!
end
Rails.application.routes.default_url_options[:host] = "localhost"

# Async adapter only works within the same process, so for manually triggering cable updates from a console,
# and seeing results in the browser, you must do so from the web console (running inside the dev process),
# not a terminal started via bin/rails console! Add "console" to any action or any ERB template view
# to make the web console appear.
development:
  adapter: solid_cable
  connects_to:
    database:
      writing: cable
  polling_interval: 0.1.seconds
  message_retention: 1.day

test:
  adapter: test

production:
  adapter: solid_cable
  connects_to:
    database:
      writing: cable
  polling_interval: 0.1.seconds
  message_retention: 1.day

web: RUBY_DEBUG_OPEN=true RUBY_DEBUG_SESSION_NAME=rails bin/rails s -p 3000
css: bin/rails tailwindcss:watch
solid_queue: bin/jobs

[jorgemanrubia]

I can't reproduce the deadlock on my side.

@miharekar I'm curious, could you try to change this line in solid_cable locally to Rails.application.executor.wrap do (instead of Rails.application.reloader.wrap do). That will take care of the original problem I detected too. I wonder if the reloader is the one causing the deadlock for you.

[npezza93]

@jorgemanrubia @miharekar Looks like i can reproduce. Swapping executor for reloader seems to fix it for me. Ill cut a release

[jorgemanrubia]

Oh fantastic @npezza93, thanks a lot 🙏

[npezza93]

Cut 3.0.4. Give it a shot and see if it crops up again

[miharekar]

Yup, seems fixed now. Thanks! 🙏