Webpacker::DevServerProxy occasionally fails

[PhilCoggins]

I've found an issue that is rather hard to replicate, but we started seeing with increased frequency in our project, particularly after we upgraded to Ruby 3.0.1. My organization makes pretty heavy usage of chunked assets, where we could request 30 or more assets at a time when we hit certain pages.

I've assembled a repro application at https://github.com/PhilCoggins/webpacker_proxy_repro.

1. Pull the code
2. Ensure you have ruby 3.0.1 installed.
3. bundle
4. yarn
5. Start a webpack-dev-server: bin/webpack-dev-server
6. Start a Rails server, with a single thread to improve chances of repro RAILS_MAX_THREADS=1 WEB_CONCURRENCY=0 bin/rails s
7. install http-rb, used in repro script gem install http
8. Start the repro script MAX_THREADS=500 ruby repro_fetch_assets_script.rb

The script tries to hit the rails server for assets as quickly as possible, if the script has ran for a while without failures, try stopping the script, restarting your rails server, and starting the script again.

The exception that you should see in your rails server logs looks like this:

Asset /packs/js/galaxy-243-81c2095cfad4fc694c5b.chunk.js.map failed!
/Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/net/http.rb:987:in `initialize': Failed to open TCP connection to localhost:3035 (Operation timed out - connect(2) for "localhost" port 3035) (Errno::ETIMEDOUT)
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/net/http.rb:987:in `open'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/net/http.rb:987:in `block in connect'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/timeout.rb:97:in `block in timeout'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/timeout.rb:107:in `timeout'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/net/http.rb:985:in `connect'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/net/http.rb:970:in `do_start'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/3.0.0/net/http.rb:965:in `start'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/rack-proxy-0.7.0/lib/rack/http_streaming_response.rb:71:in `session'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/rack-proxy-0.7.0/lib/rack/http_streaming_response.rb:60:in `response'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/rack-proxy-0.7.0/lib/rack/http_streaming_response.rb:29:in `headers'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/rack-proxy-0.7.0/lib/rack/proxy.rb:129:in `perform_request'
	from /Users/philcoggins/Workbench/webpacker_proxy_repro/config/initializers/webpacker/dev_server_proxy.rb:25:in `perform_request'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/rack-proxy-0.7.0/lib/rack/proxy.rb:63:in `call'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/railties-6.1.3.2/lib/rails/engine.rb:539:in `call'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/puma-5.3.2/lib/puma/configuration.rb:249:in `call'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/puma-5.3.2/lib/puma/request.rb:77:in `block in handle_request'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/puma-5.3.2/lib/puma/thread_pool.rb:338:in `with_force_shutdown'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/puma-5.3.2/lib/puma/request.rb:76:in `handle_request'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/puma-5.3.2/lib/puma/server.rb:438:in `process_client'
	from /Users/philcoggins/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/puma-5.3.2/lib/puma/thread_pool.rb:145:in `block in spawn_thread'

From my investigation thus far, it seems that occasionally, Net::HTTP will attempt to fetch an asset from webpack-dev-server while another response is still being streamed, which points to potential thread safety issues issues with Net::HTTP? I was able to eliminate the exceptions by writing my own proxy middleware, it looks kind of like this:

    class_attribute(:pool, default: ConnectionPool.new(size: $config["MAX_THREADS"].to_i, timeout: 30) do
      dev_server = Webpacker.instance.dev_server
      HTTP.persistent("http://#{dev_server.host}:#{dev_server.port}").timeout(3)
    end)

    def call(env)
      ...
        Rails.logger.debug("Requesting #{full_path}")
        self.class.pool.with do |conn|
          response = conn.get(full_path).flush
          [
            response.code,
            response.headers,
            [response.body.to_str]
          ]
        end
      else
        @app.call(env)
      end
    end

So I'm effectively getting the full response using an HTTP instance from a connection pool, and I call .flush on it when it has completed to ensure everything has completed successfully.

I'm happy to provide other details, just hoping I can get some more eyes on this, thanks!

[fschwahn]

I have a feeling this might be connected to puma/puma-dev#284. I set the following env variables (NOTE: you could also adjust these settings in webpacker.yml):

WEBPACKER_DEV_SERVER_HOST=127.0.0.1
WEBPACKER_DEV_SERVER_PUBLIC=127.0.0.1:3035

After these changes I haven't seen pack files time out, which was happening regularly for me before. But it is possible I'm just having a lucky run. Maybe you can verify this with your repro script?

[PhilCoggins]

@fschwahn I was actually able to resolve this by upgrading net/http. We're running 5bb14fd3bc855b4580973f4361f59f80b37e3b0b on Ruby 3.0.2 and have not had issues since upgrading. Some very low-level issues were occurring with timeouts.