Closed bopm closed 2 years ago
palkan
commented
2 years ago That could happen if AnyCable extensions haven't been activated; what is the adapter value in the cable.yml? It should be any_cable to enable all the necessary AnyCable functionality.
AnyCable works with Rails 7 fine.
bopm
commented
2 years ago @palkan:
default: &default
adapter: <%= ENV.fetch("ACTION_CABLE_ADAPTER", "any_cable") %>
development:
<<: *defaultAnyCable::Rails.enabled?
=> trueIn Ruby 3.1 output is more detailed:
anycable |
anycable | connection.handle_open
anycable | ^^^^^^^^^^^^
anycable | Did you mean? handler_for_rescue
ws | ERROR 2022-01-19T17:13:58.403Z sid=4hKoM9hdZ93UUebKl-r75 WebSocket session failed: Application error: private method `handle_open' called for #<ApplicationCable::Connection:0x0000000114e14cf8 @ids={}, @ltags=nil, @cached_ids={}, @coder=ActiveSupport::JSON, @socket=#<AnyCable::Socket:0x0000000114e14dc0 @transmissions=[], @request_env=<AnyCable::Env: url: "http://localhost:8080/cable", headers: {"cookie"=>"..."}, cstate: {}, istate: {}>, @env={"REQUEST_METHOD"=>"GET", "SCRIPT_NAME"=>"", "PATH_INFO"=>"/cable", "QUERY_STRING"=>"", "SERVER_NAME"=>"localhost", "SERVER_PORT"=>8080, "rack.url_scheme"=>"http", "rack.input"=>#<StringIO:0x0000000114e140c8>, "rack.version"=>[1, 3], "rack.errors"=>#<StringIO:0x0000000114e140a0>, "rack.multithread"=>true, "rack.multiprocess"=>false, "rack.run_once"=>false, "rack.hijack?"=>false, "HTTP_HOST"=>"localhost", "REMOTE_ADDR"=>"127.0.0.1", "anycable.raw_cstate"=>{}, "anycable.raw_istate"=>{}, "HTTP_COOKIE"=>"...", "anycable.cstate"=>#<AnyCable::Socket::State:0x0000000114e0f988 @source={}, @dirty_keys=nil>}, @cstate=#<AnyCable::Socket::State:0x0000000114e0f988 @source={}, @dirty_keys=nil>>, @subscriptions=#<ActionCable::Connection::Subscriptions:0x0000000114e0f780 @connection=#<ApplicationCable::Connection:0x0000000114e14cf8 ...>, @subscriptions={}>>So for me, it seems like in my app AnyCable somehow failing to load/monkey patch ActionCable but I cannot figure out a good way to tap into that to debug why.
bopm
commented
2 years ago At the same time socket and env are overridden by AnyCable.
bopm
commented
2 years ago @palkan I noticed you changing Monkey Patching in your Lograge fork and just in case I have it in Gemfile for this problematic application. But excluding it from Gemfile does not mitigate the problem.
bopm
commented
2 years ago Any chance of that issue being due to Zeitwerk? I tried to patch it on local, and seemingly there are bigger problems with Zeitwerk compatibility:
anycable | wrong constant name Anycable-rails
anycable |
anycable | parent.const_defined?(cname, false)
anycable | ^^^^^^^^^^^^^^^ inferred by Zeitwerk::GemInflector from fileI patched lib/anycable-rails.rb entry point like that:
# frozen_string_literal: true
require "action_cable"
require "action_cable/connection"
require "action_cable/channel"
require "action_cable/remote_connections"
require "zeitwerk"
loader = Zeitwerk::Loader.for_gem
loader.setup
require "anycable/rails"I can even get one step further with entry-point like that:
# frozen_string_literal: true
require "action_cable"
require "action_cable/connection"
require "action_cable/channel"
require "action_cable/remote_connections"
require "zeitwerk"
module Anycable
class Inflector < Zeitwerk::Inflector
def camelize(basename, abspath)
return 'Anycable' if basename.start_with?('anycable-')
super
end
end
end
loader = Zeitwerk::Loader.for_gem
loader.inflector = Anycable::Inflector.new
loader.setup
require "anycable/rails"But then it become even more odd:
anycable | expected file /Users/sergeymoiseev/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/anycable-rails-1.2.0/lib/anycable/rails.rb to define constant Anycable::Rails, but didn't
jdongelmans
commented
2 years ago I'm having the same problem, but after upgrading from Rails 6.0 to Rails 6.1(.4.4) with anycable and anycable-rails on 1.2.0.
This would indicate that indeed it's not the Rails upgrade but something else. I haven't dug any deeper yet, but just FYI.
palkan
commented
2 years ago I'm having the same problem, but after upgrading from Rails 6.0 to Rails 6.1
@jdongelmans Thanks for sharing! And what about your Ruby version?
jdongelmans
commented
2 years ago @palkan No problem and sorry 'bout that. Issues are present on both Ruby 2.7.4 and 2.7.5.
grpc tried with 1.42.0 and 1.43.1zeitwerk is on 2.5.3 in both situationspalkan
commented
2 years ago Couldn't reproduce this problem using the latest version (of everything) so far.
Does dropping require "anycable/rails/actioncable/connection" somewhere in config/application.rb help?
bopm
commented
2 years ago Adding before require 'rails/all':
anycable | uninitialized constant ActiveSupport::Autoload
anycable |
anycable | extend ActiveSupport::AutoloadAdding right after require 'rails/all' gives same issue as before.
bopm
commented
2 years ago I was able to push Zeitwerk patch further. But it still far from over:
An error occurred while loading ./spec/integrations/action_cable_compatibility.rb.
Failure/Error: require "anyway/rails"
NoMethodError:
undefined method `setting' for Anyway::Settings::Future:Class
Did you mean? String
# ./lib/anycable/config.rb:6:in `<top (required)>'I don't think hacking around with Zeitwerk is a way. AnyCable doesn't rely on it to load the patches.
Could you instead open the source files—anycable/rails/actioncable/connection.rb and action_cable/connection/base.rb—and add puts caller right in the beginning of each file (after the # frozen_string_liternal: true comment) and capture the output?
This way we can find when and why each file is loaded. If it shows that Rails' version is loaded multiple times (and after the AnyCable patch), that would explain this.
jdongelmans
commented
2 years ago Hi @palkan,
Thanks for looking into this a bit deeper. I agree, we should not work around Zeitwerk as this would probably give more headaches in the future.
I have attached the requested output for my project.
edit: I saw bootsnap in the logs and figured that might also be something that could mess up the loading, so I've tried reverting that to the last working version (1.7.3) and I've tried removing it completely, but still same issue unfortunately 😞
bopm
commented
2 years ago I am a bit amazed by such reaction for Zeitwerk, which is currently defacto standard in Ruby with Rails 7 release. It gives headaches when you break conventions and even then you have quite a lot of control. But aside from that here is my
palkan
commented
2 years ago Thanks @bopm.
So, each file is loaded just once? The order is correct.
Okay, let's try another trick: could you please open the anycable/rails/actioncable/connection.rb file and add the following right in the end of it:
ActionCable::Connection::Base.freezeI believe, we should see the FrozenError after that, showing us what else tries to modify this class. If that's something we expect, we can move #freeze there and re-try; repeat until you find a suspicious code (the one redefining #handle_open).
bopm
commented
2 years ago That helped:
anycable | can't modify frozen class: ActionCable::Connection::Base
anycable | /Users/sergeymoiseev/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/sentry-rails-5.0.1/lib/sentry/rails/railtie.rb:28:in `prepend_features'@jdongelmans are you using Sentry as well?
jdongelmans
commented
2 years ago Nice find. Indeed Sentry is also in this project and after removing it the websocket connects no problems at all 🎉
bopm
commented
2 years ago @palkan while we get to the bottom of that, disabling Sentry is not a solution for me. What are the next steps for this issue?
aenain
commented
2 years ago @palkan while we get to the bottom of that, disabling Sentry is not a solution for me. What are the next steps for this issue?
@bopm for now we've reverted all sentry gems to the latest version that doesn't capture exceptions inside ActionCable - 4.8.3
- gem 'sentry-rails', '5.0.1'
- gem 'sentry-ruby', '5.0.1'
- gem 'sentry-sidekiq', '5.0.1'
+ gem 'sentry-rails', '4.8.3'
+ gem 'sentry-ruby', '4.8.3'
+ gem 'sentry-sidekiq', '4.8.3'running rails 6.1.4.4 and ruby 2.7.5
davidbyttow
commented
2 years ago Same problem here. But, +1 to @bopm's question though, This seems like an issue with anycable-rails, no?
rromanchuk
commented
2 years ago @bopm thanks for tracking this, i started going down this rabbit hole thinking it was related to my changes for https://docs.anycable.io/anycable-go/signed_streams ruby 3.1 + edge rails 7 + turbo
... i also use sentry. Has anyone filed anything with sentry yet?
davidbyttow
commented
2 years ago Is there anything for Sentry to even do here?
rromanchuk
commented
2 years ago oops, still catching up. Just saw the last stack frame inside the gem and the version downgrade and made the wrong assumption. oh 👋 david, makes me happy (and oddly nostalgic?) to see you active here
bopm
commented
2 years ago @rromanchuk @davidbyttow to my understanding (but I really like to hear @palkan opinion) AnyCable is doing the most terrifying thing in monkey patching of preexisting base API methods visibility. The only way to make it worse is to make something public on that API private inside of AnyCable :trollface:.
palkan
commented
2 years ago Thanks @bopm!
AnyCable is doing the most terrifying thing in monkey patching of preexisting base API methods visibility
I wouldn't use "the most" though 🙂
The reasoning behind this is in keeping compatibility with our spec. Action Cable is just one of the possible adapters for AnyCable, and #handle_open (along with the #handle_close) are required APIs for implementations.
Is there anything for Sentry to even do here?
Nope, their patch is 👍
Looks like it makes sense to spend a bit more time and get rid of all the monkey-patching; stay tuned!
bopm
commented
2 years ago @palkan don't get me wrong, AnyCable is amazing piece of Rails infrastructure. Probably, correct way is to get Rails Core involved and make those methods public. Problem here is only with making them public all the sudden.
palkan
commented
2 years ago As a quick fix, I suggest adding the following somewhere in the configuration:
# in config/application.rb
initializer "anycable.sentry_hack", after: :"sentry.extend_action_cable" do
next unless defined?(::Sentry::Rails::ActionCableExtensions::Connection)
Sentry::Rails::ActionCableExtensions::Connection.send :public, :handle_open, :handle_close
endHmm this was no change for me, not sure how thats possible. I'm going to step through it on production and see what I can figure out.
palkan
commented
2 years ago You're right. Updated the patch.
palkan
commented
2 years ago Released 1.2.1 with a temporary workaround. Check it, please, and let me know if the problem still persists.
rromanchuk
commented
2 years ago @palkan i'm all over the place right now, so take this with a grain of salt
I'm noticing this coming up in staging currently
undefined method 'protocol' for nil:NilClass /lograge-c46f94686d9e/lib/lograge/rails_ext/action_cable/connection/base.rb:8:in 'block in handle_open'
I'm on
gem 'lograge', github: 'palkan/lograge'
Wasn't this the lograge/action cable issue from like two years ago? I'm currently in the middle of cleaning up my structured logs and other smelly logging cruft so i'm not convinced this is related.
bopm
commented
2 years ago @rromanchuk Lograge PR was recently accepted, return to the upstream from the fork.
rromanchuk
commented
2 years ago Everything looks healthy now 👍 , thanks
==> anycable-go.log <== D 2022-01-31T18:37:55.429Z sid=zqQ3H5RgmUjHXuJ80Fe_5 WebSocket session established D 2022-01-31T18:37:55.528Z context=rpc sid=zqQ3H5RgmUjHXuJ80Fe_5 Authenticate response: status:SUCCESS identifiers:"{}" transmissions:"{\"type\":\"welcome\"}" env:<cstate:<key:"ltags" value:"[]" > > D 2022-01-31T18:37:55.528Z context=hub sid=zqQ3H5RgmUjHXuJ80Fe_5 Registered with identifiers: {} D 2022-01-31T18:37:55.528Z context=node sid=zqQ3H5RgmUjHXuJ80Fe_5 Incoming message: &{subscribe {"channel":"UserChannel","user_id":"5846e0e0-4cff-468e-8ec8-00625c899b67"} }
leonid-shevtsov
commented
2 years ago The hack (and the patched 1.2.1 release) don't correctly work on Rails 6.1.4.4 / Ruby 3.1.0 / Sentry-rails 5.0.1.
The initializer doesn't get the proper order with after: :"sentry.extend_action_cable".
It does if the after value is passed as a string: after: "sentry.extend_action_cable".
I guess it's fine for a temporary hack. Worked around it by putting the proper initializer in config/application.rb
palkan
commented
2 years ago The initializer doesn't get the proper order with after: :"sentry.extend_action_cable".
Oh. Does moving sentry-rails before anycable-rails in the Gemfile help?
palkan
commented
2 years ago The v1.3.0 has been released with the rewritten Action Cable integration, which should help us to prevent such issues in the future.
rromanchuk
commented
2 years ago @bopm i'm getting below now. is there an easy way to disable this lograge/actioncable integration completely? Ive been playing wack-a-mole between 3 different gems now for too long
wrong number of arguments (given 1, expected 0)
lograge (bf6954566607) lib/lograge/rails_ext/action_cable/channel/base.rb in subscribe_to_channel at line 6
palkan
commented
2 years ago Thanks for reporting! Released 1.3.1 with a fix. Please, let me know if there are any other issues. I'd like to make sure we find all the edge cases with the conflicting patches, that would be helpful for everyone.
Tell us about your environment
Ruby version: 2.7/3.1
Rails version: 7.0.1
anycablegem version: 1.2.0anycable-railsgem version: 1.2.0grpcgem version: 1.42.0What did you do?
Upgrade application to Rails 7, run application.
What did you expect to happen?
AnyCable keeps working.
What actually happened?
AnyCable is not working with error: