Authenticate response: error_msg:"undefined method `protocol' for nil:NilClass"

[subhashsaran]

Tell us about your environment

Ruby version: 2.6.2

**Rails version:**5.2.2

anycable gem version: 0.6.3

**anycable-rails gem version:**0.6.4

grpc gem version: 1.17

What did you do?

I did setup anycable with existing Rails app which was using action cable earlier, I managed to have it working on dev environment but when deployed to production I get authentication error,
this issue is not related to troubleshooting but seems different.

we have deployed on heroku with two apps setup as suggested. one app is running rails application on a subdomain and another one is running anycable rpc server on another subdomain. we have supplied domain: :all option in session_store.rb.

What did you expect to happen?

Expected Anycable to work fine.

What actually happened?

Error backtrace from production.

2019-08-27T03:43:46.812300+00:00 app[web.1]: [AnyCable sid=caSj90W6eSG3l9kagpJDVD] method={} path={} format={} params={} controller=ApplicationCable::Connection action=connect status=500 error='NoMethodError: undefined method `protocol' for nil:NilClass' duration=1.33
2019-08-27T03:43:46.812368+00:00 app[web.1]: [AnyCable sid=caSj90W6eSG3l9kagpJDVD] undefined method `protocol' for nil:NilClass
2019-08-27T03:43:46.812714+00:00 app[web.1]: D 2019-08-27T03:43:46.812Z context=rpc Authenticate response: error_msg:"undefined method `protocol' for nil:NilClass"
2019-08-27T03:43:46.812907+00:00 app[web.1]: D 2019-08-27T03:43:46.812Z context=ws Websocket session initialization failed: Application error: undefined method `protocol' for nil:NilClass

[subhashsaran]

Ahh, Figured it out. issue turned out to be because we are using lograge in production which override action cable connection handler. I think anycable override somehow leave websocket to nil.
https://github.com/roidrage/lograge/blob/master/lib/lograge/rails_ext/action_cable/connection/base.rb#L8

[palkan]

Yep, that’s a lograge issue: roidrage/lograge#257 (comment)

Will add it to Troubleshooting.

[brunoalano]

Please, display a information about this on frontpage or some wiki.

[palkan]

Added information to the Troubleshooting guide: https://docs.anycable.io/#/troubleshooting?id=authentication-fails-with-undefined-method-39protocol39-for-nilnilclass

[palkan]

How are people solving this besides avoiding using lograge?

UPDATED on 2020-05-05

The best way is to fork lograge and fix the way they do the monkey-patching.
We can do this by making Ruby load proper patches instead of Lograge ones.

Here is how we can do that.

1. Create a config/lograge_fix folder with the following structure:

config/
  lograge_fix/
    lograge/
      rails_ext/
        action_cable/
          channel/
            base.rb
          connection/
            base.rb

We want to have the exact structure as [Lograge has](https://github.com/roidrage/lograge/blob/1729eab7956bb95c5992e4adab251e4f93ff9280/lib/lograge.rb#L156.

The contents of the patches are the following:

#  config/lograge_fix/lograge/rails_ext/action_cable/channel/base.rb
module Lograge
  module ActionCable
    module ChannelInstrumentation
      def subscribe_to_channel
        ActiveSupport::Notifications.instrument("subscribe.action_cable", notification_payload("subscribe")) { super }
      end

      def unsubscribe_from_channel
        ActiveSupport::Notifications.instrument("unsubscribe.action_cable", notification_payload("unsubscribe")) { super }
      end

      private

      def notification_payload(method_name)
        {channel_class: self.class.name, action: method_name}
      end
    end
  end
end

ActionCable::Channel::Base.prepend(Lograge::ActionCable::ChannelInstrumentation)


#  config/lograge_fix/lograge/rails_ext/action_cable/connection/base.rb 
module Lograge
  module ActionCable
    module ConnectionInstrumentation
      def handle_open
        ActiveSupport::Notifications.instrument("connect.action_cable", notification_payload("connect")) { super }
      end

      def handle_close
        ActiveSupport::Notifications.instrument("disconnect.action_cable", notification_payload("disconnect")) { yield }
      end

      def notification_payload(method_name)
        {connection_class: self.class.name, action: method_name, data: request.params}
      end
    end
  end
end

ActionCable::Connection::Base.prepend(Lograge::ActionCable::ConnectionInstrumentation)

2. Now we need to tell Ruby to load our patches instead of Lograge ones. For that, we should add our lograge_fix folder to the beginning of the $LOAD_PATH.

In your config/application.rb, right after require "boot" add the following line:

$LOAD_PATH.unshift(File.join(__dir__, "lograge_fix"))

That's it! Now Lograge should work correctly with Action Cable.

[palkan]

This PR provides a fix: roidrage/lograge#304

[leoc]

Thank you for the work-around, @palkan!

I had to use super for closing connections, otherwise it complained about no block given for yield:

#  config/lograge_fix/lograge/rails_ext/action_cable/connection/base.rb 
module Lograge
  module ActionCable
    module ConnectionInstrumentation
      def handle_open
        ActiveSupport::Notifications.instrument("connect.action_cable", notification_payload("connect")) { super }
      end

      def handle_close
        ActiveSupport::Notifications.instrument("disconnect.action_cable", notification_payload("disconnect")) { super }
      end

      def notification_payload(method_name)
        {connection_class: self.class.name, action: method_name, data: request.params}
      end
    end
  end
end

ActionCable::Connection::Base.prepend(Lograge::ActionCable::ConnectionInstrumentation)

[palkan]

Yeah, I've updated the PR, so you can use my fork instead of a patch.

[ryansch]

@palkan I just hit this today and found your fixed version in roidrage/lograge#310. Thanks!!