Rails 5.0.2/5.0.1 + Puma ActionCable connection issue

[edwardmp]

Steps to reproduce

Open puma.rb and add SSL certificates:

ssl_key = File.expand_path '../certificates/server.key', __FILE__
ssl_cert = File.expand_path '../certificates/server.crt', __FILE__
bind "ssl://127.0.0.1:3000?key=#{ssl_key}&cert=#{ssl_cert}"
# Set on development.rb to force SSL and allowed origin request for ActionCable:
...
config.force_ssl = true
config.action_cable.allowed_request_origins = ['https://lvh.me:4000']

In my settings I use redis:

development:
  adapter: redis
  url: redis://localhost:6379/1

Expected behavior

The connection using ActionCable works seamlessly with SSL, just as it does for non-SSL connections.

Actual behavior

If I try to use SSL, this warning message is shown in the client's browser console:

WebSocket connection to 'wss://lvh.me:3000/cable' failed: WebSocket is closed before the connection is established.

System configuration

Ruby version: ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-linux]
Rails version: Rails 5.0.2 (also confirmed to be not working on 5.0.1, but did work fine in 5.0.0.1)

Borrowed from puma/puma#1189, seeing same issue as user there.
Related issues: #27625, #27421

[rafaelfranca]

This seems to be an issue in puma. cc @schneems

[rafaelfranca]

Also cc @matthewd since it is related to 5d92089

[edwardmp]

@rafaelfranca it could be but I can say this:
I've used the same Puma gem version (3.6) for the past few months. In combination with Rails 5.0.0.1 everything worked as expected. With Rails 5.0.1 and 5.0.2 it does no longer work. So if it's Puma it wasn't caused by any code change on their part, only the interaction with Rails. I did confirm that the newest Puma gem version (3.7) doesn't make a difference with regard to this issue.

[wonderer007]

is it the same issue as this websocket-rails/websocket-rails#399 (comment)

[edwardmp]

@wonderer007
It doesn't appear so, the error message in the client browser is different (does not mention handshake)

[maclover7]

@edwardmp Can you confirm that if you keep the Puma version constant, only upgrading from Rails 5.0.0.1 to 5.0.2 introduces this issue for you?

[edwardmp]

@maclover7
Good question. Actually I haven't yet but it was definitely on my mind. Let me try that and get back to you.

I just noticed that different versions of the ActionCable dependency nio4r are used when on 5.0.0.1 or 5.0.1/5.02 (1.2.1 vs 2.0.0). This might also affect this issue.

[edwardmp]

@maclover7
It's confirmed: downgrading to 5.0.0.1 shows the issue is not present when using that version. It then broke when 5.0.1 was released and continued to be present in 5.0.2.

[maclover7]

Dug into this, turns out this is an issue with Puma...

Starting with this commit, on this line, Action Cable calls @rack_hijack_io.write_nonblock to write data out to the socket. However, this code depends on the 99% case where @rack_hijack_io is a TCPSocket / IO. When using Puma, @rack_hijack_io is actually an instance of Puma::MiniSSL::Socket, which does not implement the write_nonblock method (it does implement the read_nonblock method...). My take on how to fix this would be for Puma to conform to TCPSocket's API, and to implement the write_nonblock method.

cc puma folks @schneems @nateberkopec @evanphx

[edwardmp]

@maclover7 Great that you'd be able to find this out! Sounds logical, but why aren't we seeing any exceptions being raised after a non-existing method is called on Puma::MiniSSL::Socket?

Edit:
Think I got the answer from #27421 (comment) where a very similar issue arose with Passenger due to another kind of incompatibility (also originating from calling write_nonblock):

The Rails team may also want to fix the fact that any errors inside ActionCable::Connection::Stream#write may be silently swallowed.

ActionCable::Connection#write is called from ActionCable::Connection::ClientSocket#write, which catches any errors and emits them over the socket using emit_error. But if it is the socket write itself that fails, then emit_error fails as well, causing the error to be swallowed. More sophisticated error handling may be appropriate here.

This indeed sounds like a good thing to implement. I can try to create a PR with different error handling, but what's appropriate here? It probably wouldn't be a good idea to just throw a plain exception when a socket error occurs, but what else can we realistically use, just a log message indicating the error? The latter at least gives users some clue to what might be happening causing an issue like this.

[matthewd]

Yeah, please do see what seems reasonable. I think the problem with keeping an exception is just that we don't have anywhere sane to raise it.

Failing that, and assuming we're not "legitimately" eating some other exceptions that we want to be silent, a log message does seem like a reasonable minimum.

[edwardmp]

@matthewd
Great, I'll look into that in the coming days.

On the side of Puma though, this might be a hard nut to crack: they in turn call TCPServer or UnixServer (depending on platform used), neither of which implements write_nonblock functionality. Nevermind, they inherit from IO, which does implement write_nonblock. I'll even see If I can give a stab for a Puma PR fixing this.

[nateberkopec]

@edwardmp Please do!

[edwardmp]

Here is a oneliner logging all socket write errors:
edwardmp@2de531a

This needs work though, as I need to call Rails.logger to access the logger, because the logger dependency isn't injected in this class yet.

[edwardmp]

Hi @schneems @nateberkopec @evanphx,

I've looked into this and tried a few things, simply creating a method similar to the existing write method to primarily just call the socket's write_nonblock method in turn. Unfortunately this did not appear to work/fix the issue, probably there need to be other changes to the existing method code. I think my socket related knowledge is insufficient atm to create a proper fix, so I hope one of you is able to figure this out without spending to much time.

Thanks in advance!

[djones]

I get this issue too. Rails 5.0.2 (5.1.0.rc1 also), Puma 3.8.2, Ruby 2.4.1p111

[djones]

In the browser I get:

WebSocket connection to 'wss://localhost:3001/cable' failed: WebSocket is closed before the connection is established.

The Rails log loops over these lines when the browser tries to make the connection but can't establish it:

Started GET "/cable" for ::1 at 2017-04-11 17:04:39 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-11 17:04:39 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for ::1 at 2017-04-11 17:04:45 -0700
Started GET "/cable" for ::1 at 2017-04-11 17:04:46 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-11 17:04:46 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for ::1 at 2017-04-11 17:04:49 -0700
Started GET "/cable" for ::1 at 2017-04-11 17:04:49 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-11 17:04:49 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)

If I change config.action_cable.url to use HTTP (in my case ws://localhost:3000/cable) and I disable forcing SSL... it starts working just fine like so:

Finished "/cable/" [WebSocket] for ::1 at 2017-04-11 17:06:55 -0700
Started GET "/cable" for ::1 at 2017-04-11 17:06:55 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-11 17:06:55 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
ReportsChannel is transmitting the subscription confirmation
ReportsChannel is streaming from reports

[edwardmp]

Submitted a PR to start logging socket write errors: #28757

The folks over at Puma (puma/puma#1189) have a temporary fix for the issue on their part (not implementing write_nonblock and read_nonblock methods). If this can be merged in I think we can close this issue :)

cc @rafaelfranca

[zerocool4u2]

config.action_cable.url = 'ws:lvh.me:3000/cable' solved it for me, thanks @djones
notice ws instead wss, I'm guessing wss stands for websocket secure?