Puma: Issue with WebSocket through SSL

[brunowego]

Steps to reproduce

1) 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}"

2) 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']
...

3) In my settings I use redis:

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

Expected behavior

The connection using ActionCable works seamlessly without SSL.

Actual behavior

If try use SSL, the warning message is shown:

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

System configuration

Ruby version: ruby 2.3.2p217 (2016-11-15 revision 56796) [x86_64-darwin16]
Rails version: Rails 5.0.1

[brunowego]

Similar issue reported at https://github.com/rails/rails/issues/27625

[brunowego]

The issue is in Rails 5.0.1, reported here https://github.com/rails/rails/issues/27421

[brunowego]

I solved with downgrade to version of Rails 5.0.0.1.

[edwardmp]

I'm still seeing this issue on Rails 5.0.2. Will open issue on Rails github.

[whitehat101]

I've reviewed the referenced rails issue, and this does appear to be from a quirk with Puma's minissl, so I thought I'd bump here instead of there. To use SSL+WebSockets I either need to lock rails to 5.0.0.1 or find someone other than Puma to do SSL termination, and I'm not excited about either.

https://github.com/rails/rails/issues/28362#issuecomment-285903720

My take on how to fix this would be for Puma to conform to TCPSocket's API, and to implement the write_nonblock method.

Do you agree that that is (part of) the long term solution?

I see @edwardmp mentions trying things with write_nonblock, but I wasn't able to find a branch or code. Could you share those efforts, or call out the blocks of code that need to be massaged?

I expect around: https://github.com/puma/puma/blob/0b3626091e7ca7013312586a54a2f6c150f861b7/lib/puma/minissl.rb#L57-L78

[djones]

I just generally want to bump this issue. It completely blocks me from being able to use ActionCable. I tried Rails 5.1.0.rc1 and things remain broken there too.

Using Rails 5.0.0.1 as a fix is a poor option. That particular version of Rails has other issues that you would have to accept.

[edwardmp]

@whitehat101 @djones
Yes that's the issue and for me too this makes ActionCable unusable in 5.0.1.
I know nothing about sockets so my fixes were just to determine if that was the actual issue (e.g. rerouting write_nonblock to the normal write method)

The only thing that would need to be done is Puma's MiniSSL socket implemeting the write_nonblock method.

[djones]

I know very little about websockets but I was able to figure _some_ stuff out.

Indeed if you implement #write_nonblock in minissl.rb it does get called from ActionCable.

The method signature should be something like

def write_nonblock(data, *args)

I found this in the Passenger project: https://github.com/phusion/passenger/blob/stable-5.1/src/ruby_supportlib/phusion_passenger/utils/unseekable_socket.rb#L120-L124 and they recently added support for arguments.

Somewhere in this method it should call @socket.write_nonblock enc, *args instead of @socket.write enc which is what the write (blocking) method calls.

[evanphx]

Hi all, I'm suggest the fix in #1274 for now. It's not perfect but it will get y'all working again.

[djones]

@evanphx thanks for looking into this issue! Really appreciated!

I actually tried out a similar idea to what you had and it doesn't fix the issue. I'd be interested to hear from others if #1274 fixes things for them.

Using the #1274 version of puma, I continue to see this cycle in my Rails log:

Started GET "/cable" for ::1 at 2017-04-13 19:11:35 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:35 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:41 -0700
Started GET "/cable" for ::1 at 2017-04-13 19:11:41 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:41 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:44 -0700
Started GET "/cable" for ::1 at 2017-04-13 19:11:45 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:45 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)
Finished "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:50 -0700
Started GET "/cable" for ::1 at 2017-04-13 19:11:50 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 19:11:50 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)

Upgrading the connection, finishing it, upgrading, finishing etc. Here's the view from the browser:

Simply responding to write_nonblock calls doesn't seem to be enough.

When I make the request with the exact same codebase over non-SSL instead, I get no warnings in the console of the browser and I see this in my Rails log

Started GET "/cable" for ::1 at 2017-04-13 19:14:52 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 19:14:52 -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

It does not repeatedly try to upgrade the connection to WebSocket. It just settles like this and it works as expected.

Any ideas? What would cause the browser to think the connection wasn't actually upgraded and therefore make repeated requests? Or what would trigger the finishing of the connection?

Happy to work with you on this one @evanphx

[evanphx]

@djones Just to confirm, websockets not over SSL work fine?

[evanphx]

@djones I just pushed a change to #1274 after consulting the actioncable code. Would you be willing to try the fix and see if things work for you?

[djones]

@evanphx confirming websockets not over SSL works fine.

Trying out the latest change now.

[djones]

Weird. I still have the same issue. I threw a binding.pry into write_nonblock(data, *_) and it definitely is being called.

I'll create a barebones example Rails app just to be 100% certain it isn't something specific to my app. And that will give us something to test against too.

Here's the result of putting binding.pry into the method and inspecting data each time.

From: /Users/djones/Code/puma/lib/puma/minissl.rb @ line 91 Puma::MiniSSL::Socket#write_nonblock:

    89: def write_nonblock(data, *_)
    90:   binding.pry
 => 91:   write data
    92: end

[1] pry(#<Puma::MiniSSL::Socket>)> data
=> "HTTP/1.1 101 Switching Protocols\r\n" +
"Upgrade: websocket\r\n" +
"Connection: Upgrade\r\n" +
"Sec-WebSocket-Accept: tKPIqJ0uLj3sVkKF/l2maJZ+BRk=\r\n" +
"Sec-WebSocket-Protocol: actioncable-v1-json\r\n" +
"\r\n"
[2] pry(#<Puma::MiniSSL::Socket>)> exit

From: /Users/djones/Code/puma/lib/puma/minissl.rb @ line 91 Puma::MiniSSL::Socket#write_nonblock:

    89: def write_nonblock(data, *_)
    90:   binding.pry
 => 91:   write data
    92: end

[1] pry(#<Puma::MiniSSL::Socket>)> data
=> "\x81\x12{\"type\":\"welcome\"}"
[2] pry(#<Puma::MiniSSL::Socket>)> exit

From: /Users/djones/Code/puma/lib/puma/minissl.rb @ line 91 Puma::MiniSSL::Socket#write_nonblock:

    89: def write_nonblock(data, *_)
    90:   binding.pry
 => 91:   write data
    92: end

[1] pry(#<Puma::MiniSSL::Socket>)> data
=> "\x81${\"type\":\"ping\",\"message\":1492139027}"
[2] pry(#<Puma::MiniSSL::Socket>)> exit
Finished "/cable/" [WebSocket] for ::1 at 2017-04-13 20:03:50 -0700
Started GET "/cable" for ::1 at 2017-04-13 20:03:50 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 20:03:50 -0700
Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: Upgrade, HTTP_UPGRADE: websocket)

From: /Users/djones/Code/puma/lib/puma/minissl.rb @ line 91 Puma::MiniSSL::Socket#write_nonblock:

    89: def write_nonblock(data, *_)
    90:   binding.pry
 => 91:   write data
    92: end

[1] pry(#<Puma::MiniSSL::Socket>)> data
=> "HTTP/1.1 101 Switching Protocols\r\n" +
"Upgrade: websocket\r\n" +
"Connection: Upgrade\r\n" +
"Sec-WebSocket-Accept: zqqTAeqCtj9LSF0Hv2H4OIhD/LQ=\r\n" +
"Sec-WebSocket-Protocol: actioncable-v1-json\r\n" +
"\r\n"
[2] pry(#<Puma::MiniSSL::Socket>)> exit

From: /Users/djones/Code/puma/lib/puma/minissl.rb @ line 91 Puma::MiniSSL::Socket#write_nonblock:

    89: def write_nonblock(data, *_)
    90:   binding.pry
 => 91:   write data
    92: end

[1] pry(#<Puma::MiniSSL::Socket>)> data
=> "\x81\x12{\"type\":\"welcome\"}"
[2] pry(#<Puma::MiniSSL::Socket>)> exit
Finished "/cable/" [WebSocket] for ::1 at 2017-04-13 20:03:56 -0700

It seems to repeat a welcome message.

[djones]

@evanphx any idea what causes the connection to finish?

That seems to be the core difference. Non-SSL opens the connection, upgrades it, and then my application specific code starts to appear, and that's the end. It stays open as expected.

E.g.

Started GET "/cable" for ::1 at 2017-04-13 19:14:52 -0700
Started GET "/cable/" [WebSocket] for ::1 at 2017-04-13 19:14:52 -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

But over SSL it seems to open, upgrade, finish, repeat forever. Even after we know write_nonblock is being called.

[evanphx]

@djones So I went through the actioncable code that made the changes to this code path and found that they're using a read_nonblock(data, exception: false) variant that minissl didn't support either. I've made the change to support that and pushed to that PR. Wanna give it a spin again?

[djones]

@evanphx it works now! 🎊

[evanphx]

@djones WOONDERFUL! I'll merge that in and get a release out tomorrow with the fixes. I'll chat with the actioncable folks about not masking these sorts of errors (which they must be).

[edwardmp]

@evanphx @djones
This is great! I actually thought about something similar (stubbing those methods out) but thought that would be unacceptable.

@djones actually they already know errors like these are masked (they are ignoring any errors; the actual error handling method has an empty body...) so my proposal was to simply log these messages: see https://github.com/rails/rails/issues/28362#issuecomment-285904683

[edwardmp]

@evanphx
I'm working towards properly logging socket errors.
Hopefully I can submit this PR to the Rails team later today.

Edit: Rails PR submitted: https://github.com/rails/rails/pull/28757

[edwardmp]

@evanphx my Rails PR for extra logging has been merged in. Can you merge this fix in and release a new Puma version in the coming week so I can finally use ActionCable again?

[edwardmp]

@evanphx bump. I'm not sure everyone is aware that ActionCable is completely broken in combination with Rails 5.0.1+ without this patch

[nateberkopec]

Working on a release now, closing because it's merged on master.

[risinglf]

@nateberkopec how is going with the new Puma release? AFAIK the 3.8.2 does not have that fix, right?

thank you so much

[slehmann36]

Is there an update on this? I can't see this issue references in any release notes...

As others have mentioned, ActionCable is broken as of Rails v5.0.1 until this fix is released. Please release it at earliest convenience so everyone can start using ActionCable again...

Thanks

[nateberkopec]

Hi folks - this was merged here https://github.com/puma/puma/commit/7cd363f7990f956334364ccdecf0b21f5fe65143 and is available in 3.9.0+

[wdiechmann]

Any ideas what I'm to do? I'm seeing this in production on Rails 5.2.0 and Puma 3.11 - from this thread I was under the impression that the issue was only in development, and already solved?

My development env has ActionCable working ok - but when I deploy to production (with NgINX in front of puma with the conf below) this is what my log/production.log tells me

I, [2019-05-20T06:29:15.602963 #10201]  INFO -- : [35efda4b-0f24-4642-9c8f-b25fe7649f09] Started GET "/cable" for 92.246.28.33 at 2019-05-20 06:29:15 +0200
I, [2019-05-20T06:29:15.603595 #10201]  INFO -- : [35efda4b-0f24-4642-9c8f-b25fe7649f09] Started GET "/cable/" [WebSocket] for 92.246.28.33 at 2019-05-20 06:29:15 +0200
I, [2019-05-20T06:29:15.603693 #10201]  INFO -- : [35efda4b-0f24-4642-9c8f-b25fe7649f09] Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: upgrade, HTTP_UPGRADE: websocket)
D, [2019-05-20T06:29:15.607244 #10201] DEBUG -- :   User Load (1.0ms)  SELECT  `users`.* FROM `users` WHERE `users`.`deleted_at` IS NULL AND `users`.`id` = 1 LIMIT 1
I, [2019-05-20T06:29:15.608120 #10201]  INFO -- : [ActionCable] [supervip] Registered connection (Z2lkOi8vc3BlaWNoZXIvVXNlci8x)
I, [2019-05-20T06:29:26.794676 #10201]  INFO -- : [ActionCable] [supervip] Finished "/cable/" [WebSocket] for 92.246.28.33 at 2019-05-20 06:29:26 +0200
I, [2019-05-20T06:29:28.108587 #10201]  INFO -- : [99ab0747-3fcb-4440-a527-3e92a542a2f2] Started GET "/cable" for 92.246.28.33 at 2019-05-20 06:29:28 +0200
I, [2019-05-20T06:29:28.109198 #10201]  INFO -- : [99ab0747-3fcb-4440-a527-3e92a542a2f2] Started GET "/cable/" [WebSocket] for 92.246.28.33 at 2019-05-20 06:29:28 +0200
I, [2019-05-20T06:29:28.109291 #10201]  INFO -- : [99ab0747-3fcb-4440-a527-3e92a542a2f2] Successfully upgraded to WebSocket (REQUEST_METHOD: GET, HTTP_CONNECTION: upgrade, HTTP_UPGRADE: websocket)
D

In Chrome this is what I see:

WebSocket connection to 'wss://speicher.ltd/cable' failed: WebSocket is closed before the connection is established.

My NgINX conf:

# Upstream server (Puma socket)
upstream speicher {
  server unix:/var/www/speicher/shared/tmp/sockets/puma.sock;
}

# Config for vhost
server {
  listen 80;
  server_name speicher.ltd;
  return 301 https://$host$request_uri;
 }
 server {
  listen 443 ssl; # managed by Certbot
  server_name speicher.ltd;
  client_max_body_size 4G;

  access_log /var/log/nginx/speicher.access.log;
  error_log /var/log/nginx/speicher.error.log;

  root /var/www/speicher/current/public;

  # direct to maintenance if this file exists
  if (-f $document_root/system/maintenance.html) {
    rewrite  ^(.*)$  /system/maintenance.html last;
    break;
  }

  ssl_certificate /etc/letsencrypt/live/speicher.ltd/fullchain.pem; # managed by Certbot
  ssl_certificate_key /etc/letsencrypt/live/speicher.ltd/privkey.pem; # managed by Certbot
  include /etc/letsencrypt/options-ssl-nginx.conf; # managed by Certbot
  ssl_dhparam /etc/letsencrypt/ssl-dhparams.pem; # managed by Certbot

  # assets caching
  location ~ ^/(assets)/ {
    access_log  off;
    # gzip_static on;
    expires     max;
    add_header  Cache-Control public;
    add_header  Last-Modified "";
    add_header  ETag "";

    open_file_cache          max=1000 inactive=500s;
    open_file_cache_valid    600s;
    open_file_cache_errors   on;
    break;
  }

  # serve static file directly
  try_files $uri/index.html $uri @speicher;

  # App proxying
  location @speicher {
    proxy_redirect     off;
    proxy_set_header   X-Real-IP $remote_addr;
    proxy_set_header   X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header   X-Forwarded-Proto $scheme;
    proxy_set_header   Host $host;
    proxy_set_header   X-NginX-Proxy true;
    proxy_set_header   Connection "";
    proxy_http_version 1.1;
    proxy_pass         http://speicher;
  }

  location /cable {
    proxy_pass http://speicher;
    proxy_http_version 1.1;
    proxy_set_header Upgrade $http_upgrade;
    proxy_set_header Connection "upgrade";
  }


  error_page 500 502 503 504 /500.html;
  keepalive_timeout 10;

  location = /favicon.ico {
    expires    max;
    add_header Cache-Control public;
  }
}

[slehmann36]

@wdiechmann This is a working /cable location block running Rails 5.2.1

location /cable {
  proxy_pass http://puma;
  proxy_http_version 1.1;
  proxy_set_header Upgrade $http_upgrade;
  proxy_set_header Connection "Upgrade";
  proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
  proxy_set_header Host $http_host;
  proxy_redirect off;
  proxy_set_header X-Forwarded-Proto $scheme;
}

Looks pretty similar to yours, just a little more fleshed-out. See how it goes.

[wdiechmann]

Thx <3

Den 20. maj 2019 kl. 08.38 skrev Simon Lehmann [e-mail]:

@wdiechmann https://github.com/wdiechmann This is a working /cable location block running Rails 5.2.1

location /cable {
proxy_pass http://puma;
proxy_http_version 1.1;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection "Upgrade";
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header Host $http_host;
proxy_redirect off;
proxy_set_header X-Forwarded-Proto $scheme;
}
Looks pretty similar to yours, just a little more fleshed-out. See how it goes.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub https://github.com/puma/puma/issues/1189?email_source=notifications&email_token=AABPFXP32APBOLWUHWLC2Z3PWJBOBA5CNFSM4C4OL332YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODVX2QWI#issuecomment-493856857, or mute the thread https://github.com/notifications/unsubscribe-auth/AABPFXKF6NAQWUDBTRZU2MLPWJBOBANCNFSM4C4OL33Q.

[ { "@context": "http://schema.org", "@type": "EmailMessage", "potentialAction": { "@type": "ViewAction", "target": "https://github.com/puma/puma/issues/1189?email_source=notificationsu0026email_token=AABPFXP32APBOLWUHWLC2Z3PWJBOBA5CNFSM4C4OL332YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODVX2QWI#issuecomment-493856857", "url": "https://github.com/puma/puma/issues/1189?email_source=notificationsu0026email_token=AABPFXP32APBOLWUHWLC2Z3PWJBOBA5CNFSM4C4OL332YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODVX2QWI#issuecomment-493856857", "name": "View Issue" }, "description": "View this Issue on GitHub", "publisher": { "@type": "Organization", "name": "GitHub", "url": "https://github.com" } } ]