O&S isn't sending deprecations to O&S

[wjessop]

I can kinda understand this in production as it would have to make HTTP requests to the other side of the load balancer, something that some load balancers don't like, but it should work from CI.

The "wrong side of the load balancer" thing should be fixed with an external event handling endpoint.

Probably related to:

I, [2023-11-21T02:53:57.413300 #37]  INFO -- : Initialising the OAS Ruby agent
** [Own & Ship][2023-11-21 02:53:57 +0000 dd8211ad-500d-411f-8096-537128b3134d (37)] INFO : Reading configuration from /app/config/own_and_ship.yml
** [Own & Ship][2023-11-21 02:53:57 +0000 dd8211ad-500d-411f-8096-537128b3134d (37)] INFO : Reading configuration from /app/config/own_and_ship.yml
** [Own & Ship][2023-11-21 02:53:57 +0000 dd8211ad-500d-411f-8096-537128b3134d (37)] INFO : Alias parsing was not enabled. To enable it, pass `aliases: true` to `Psych::load` or `Psych::safe_load`.
** [Own & Ship][2023-11-21 02:53:57 +0000 dd8211ad-500d-411f-8096-537128b3134d (37)] INFO : The Own & Ship agent in the production environment for application  will be disabled

[wjessop]

The change didn't fix it, though it did get rid of the "Alias parsing was not enabled" message.

[caius]

We paired in this recently. Rails changed in 7.1 which appears to be why Oas isn't reporting to itself.

ActiveSupport::Deprecation stopped being a singleton and now there are multiple deprecators in a collection on Rails.application.

For some reason OasAgent's receiver isn't being injected into these deprecators and therefore isn't being sent any deprecations.

Suspected possibly load order, but if we hook before the deprecators are created the collection object should pass our receiver as a behaviour, and if we set ourselves after they are created the collection should also pass us through.

Potentially relevant PRs:

• https://github.com/rails/rails/pull/46049
• https://github.com/rails/rails/pull/46550

Needs more investigation, and possibly we gate how we attach the agent in rails >= 7.1 to use the new world.

Gems also using AS::D are supposed to lean on the collection, but they might follow the (semi helpful) warning from AS::D.warn and create a new Deprecation object directly, at which point our behaviour isn't injected.

[wjessop]

Should mostly be fixed by https://github.com/orgs/Own-and-Ship/projects/1/views/1?pane=issue&itemId=47034324

[wjessop]

I did some digging to find out why we're not getting deps on production. this is Rails 6, heroku production console.

The summary, it seems that the the receiver isn't getting called at all. If it is called directly then it works as expected.

irb(main):006:0> pp ActiveSupport::Deprecation.behavior
[#<Proc:0x00007fcc0d202458 /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/deprecation/behaviors.rb:37 (lambda)>,
 #<OasAgent::Agent::Receiver:0x00007fcbffe03968
  @rails_root="/app",
  @rails_version="6.1.7.6",
  @reporter=
   #<OasAgent::Agent::Reporter:0x00007fcbffe03d78
    @event_cache=
     #<OasAgent::Agent::EventsCache:0x00007fcbffe00e48
      @events={},
      @program_root="/app">,
    @rails_env="production",
    @rails_root="/app",
    @report_queue=#<Thread::SizedQueue:0x00007fcbffe03d50>,
    @reporter_thread=
     #<Proc:0x00007fcbffe03b70 /app/vendor/bundle/ruby/2.7.0/bundler/gems/oas_agent-60322008dba6/lib/agent/reporter.rb:47>>>]
=> [#<Proc:0x00007fcc0d202458 /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/deprecation/behaviors.rb:37 (lambda)>, #<OasAgent::Agent::Receiver:0x00007fcbffe03968 @reporter=#<OasAgent::Agent::Reporter:0x00007fcbffe03d78 @report_queue=#<Thread::SizedQueue:0x00007fcbffe03d50>, @reporter_thread=#<Proc:0x00007fcbffe03b70 /app/vendor/bundle/ruby/2.7.0/bundler/gems/oas_agent-60322008dba6/lib/agent/reporter.rb:47>, @rails_env="production", @rails_root="/app", @event_cache=#<OasAgent::Agent::EventsCache:0x00007fcbffe00e48 @program_root="/app", @events={}>>, @rails_root="/app", @rails_version="6.1.7.6">]

irb(main):008:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get(:@report_queue)
nil

irb(main):012:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get("@reporter")
#<OasAgent::Agent::Reporter:0x00007fcbffe03d78
 @event_cache=
  #<OasAgent::Agent::EventsCache:0x00007fcbffe00e48
   @events={},
   @program_root="/app">,
 @rails_env="production",
 @rails_root="/app",
 @report_queue=#<Thread::SizedQueue:0x00007fcbffe03d50>,
 @reporter_thread=
  #<Proc:0x00007fcbffe03b70 /app/vendor/bundle/ruby/2.7.0/bundler/gems/oas_agent-60322008dba6/lib/agent/reporter.rb:47>>
=> #<OasAgent::Agent::Reporter:0x00007fcbffe03d78 @report_queue=#<Thread::SizedQueue:0x00007fcbffe03d50>, @reporter_thread=#<Proc:0x00007fcbffe03b70 /app/vendor/bundle/ruby/2.7.0/bundler/gems/oas_agent-60322008dba6/lib/agent/reporter.rb:47>, @rails_env="production", @rails_root="/app", @event_cache=#<OasAgent::Agent::EventsCache:0x00007fcbffe00e48 @program_root="/app", @events={}>>

irb(main):014:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get("@reporter").instance_variable_get(:@report_queue).size
0

Testing the reporter, does it get the data?

# Look at the reporter instance queue:
> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get("@reporter").instance_variable_get(:@report_queue)
#<Thread::SizedQueue:0x00007fcbffe03d50>

# Create a new queue to replace it
irb(main):015:0> my_queue = Queue.new
=> #<Thread::Queue:0x00007fcbfda73cf0>

# Replace the reporter queue with my own
irb(main):016:0> ActiveSupport::Deprecation.behavior.last.instance_variable_get("@reporter").instance_variable_set(:@report_queue, my_queue)
=> #<Thread::Queue:0x00007fcbfda73cf0>

# Check it's in place
irb(main):017:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get("@reporter").instance_variable_get(:@report_queue)
#<Thread::Queue:0x00007fcbfda73cf0>

# Create a deprecation 
irb(main):018:0> ActiveSupport::Deprecation.new.warn "test"
DEPRECATION WARNING: test (called from <main> at /app/bin/rails:5)
=> "DEPRECATION WARNING: test (called from <main> at /app/bin/rails:5)"

# The queue is still empty
irb(main):019:0> my_queue.size
=> 0

Seemingly no data is received, how about the receiver?

# Check the existing value of @reporter:
irb(main):020:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get("@reporter")
#<OasAgent::Agent::Reporter:0x00007fcbffe03d78
 @event_cache=
  #<OasAgent::Agent::EventsCache:0x00007fcbffe00e48
   @events={},
   @program_root="/app">,
 @rails_env="production",
 @rails_root="/app",
 @report_queue=#<Thread::Queue:0x00007fcbfda73cf0>,
 @reporter_thread=
  #<Proc:0x00007fcbffe03b70 /app/vendor/bundle/ruby/2.7.0/bundler/gems/oas_agent-60322008dba6/lib/agent/reporter.rb:47>>

# Create a new queue
irb(main):022:0> my_queue = Queue.new
=> #<Thread::Queue:0x00007fcc073191a8>

# Set it
irb(main):023:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_set(:@reporter, my_queue)
#<Thread::Queue:0x00007fcc073191a8>

# Check it
=> #<Thread::Queue:0x00007fcc073191a8>
irb(main):024:0> pp ActiveSupport::Deprecation.behavior.last.instance_variable_get(:@reporter)
#<Thread::Queue:0x00007fcc073191a8>
=> #<Thread::Queue:0x00007fcc073191a8>

# Create a deprecation
irb(main):025:0> ActiveSupport::Deprecation.new.warn "test"
DEPRECATION WARNING: test (called from <main> at /app/bin/rails:5)
=> "DEPRECATION WARNING: test (called from <main> at /app/bin/rails:5)"

# Check we received it
irb(main):027:0> my_queue.size
=> 0

If I call the receiver method directly I get data:

irb(main):028:0> pp ActiveSupport::Deprecation.behavior.last.call("test", ["a", "b"])
#<Thread::Queue:0x00007fcc073191a8>
=> #<Thread::Queue:0x00007fcc073191a8>

irb(main):030:0> my_queue.size
=> 1

irb(main):031:0> pp my_queue.pop
{:type=>"rails", :version=>"6.1.7.6", :message=>"test", :callstack=>["a", "b"]}
=> {:type=>"rails", :version=>"6.1.7.6", :message=>"test", :callstack=>["a", "b"]}

[wjessop]

Dropping all deprecation behaviours except one O&S still doesn't get called:

# Check the behaviour
irb(main):033:0> ActiveSupport::Deprecation.behavior 
=> [#<Proc:0x00007fcc0d202458 /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/deprecation/behaviors.rb:37 (lambda)>, #<OasAgent::Agent::Receiver:0x00007fcbffe03968 @reporter=#<Thread::Queue:0x00007fcc073191a8>, @rails_root="/app", @rails_version="6.1.7.6">]

# Drop the proc at the start
irb(main):034:0> ActiveSupport::Deprecation.behavior.shift
=> #<Proc:0x00007fcc0d202458 /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.6/lib/active_support/deprecation/behaviors.rb:37 (lambda)>

# Check it, O&S is the only element
irb(main):035:0> ActiveSupport::Deprecation.behavior 
=> [#<OasAgent::Agent::Receiver:0x00007fcbffe03968 @reporter=#<Thread::Queue:0x00007fcc073191a8>, @rails_root="/app", @rails_version="6.1.7.6">]

# Create a deprecation
irb(main):036:0> ActiveSupport::Deprecation.new.warn "test"
DEPRECATION WARNING: test (called from <main> at /app/bin/rails:5)
=> "DEPRECATION WARNING: test (called from <main> at /app/bin/rails:5)"

# Check my queue
irb(main):037:0> my_queue.size
=> 0

[wjessop]

irb(main):001:0>  Rails.application.config.active_support.deprecation
=> :notify

[wjessop]

Interesting, loaded a production O&S console:

irb(main):001> ActiveSupport::Deprecation.behavior
=> [#<Proc:0x00007fca276f3ee0 /app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.2/lib/active_support/deprecation/behaviors.rb:135 (lambda)>]

No O&S. There's an O&S instance available elsewhere we can pinch:

irb(main):008> Rails.application.deprecators.instance_variable_get(:@options).first[1].first
=> 
#<OasAgent::Agent::Receiver:0x00007fca276fc8d8
 @rails_root="/app",
 @rails_version="7.1.2",
 @reporter=
  #<OasAgent::Agent::Reporter:0x00007fca2760cea0
   @connection=
    #<OasAgent::Agent::Connection:0x00007fca2651f278
     @conn=#<Net::HTTP ownandship.io:443 open=true>,
     @default_headers={"Content-Encoding"=>"identity", "Host"=>"ownandship.io", "Accept"=>"text/plain; api_version=1", "X-API-Token"=>"snip"}>,
   @event_cache=#<OasAgent::Agent::EventsCache:0x00007fca26527450 @events={}, @program_root="/app">,
   @rails_env="production",
   @rails_root="/app",
   @report_queue=#<Thread::SizedQueue:0x00007fca276fcd88>,
   @reporter_thread=#<Proc:0x00007fca276fca68 /app/vendor/bundle/ruby/3.3.0/bundler/gems/oas_agent-0863a2ae5243/lib/agent/reporter.rb:50>>>

Add it to AS behaviors:

irb(main):009> ActiveSupport::Deprecation.behavior << Rails.application.deprecators.instance_variable_get(:@options).first[1].first
=> 
[#<Proc:0x00007fca276f3ee0 /app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.2/lib/active_support/deprecation/behaviors.rb:135 (lambda)>,
 #<OasAgent::Agent::Receiver:0x00007fca276fc8d8
  @rails_root="/app",
  @rails_version="7.1.2",
  @reporter=
   #<OasAgent::Agent::Reporter:0x00007fca2760cea0
    @connection=
     #<OasAgent::Agent::Connection:0x00007fca2651f278
      @conn=#<Net::HTTP ownandship.io:443 open=true>,
      @default_headers={"Content-Encoding"=>"identity", "Host"=>"ownandship.io", "Accept"=>"text/plain; api_version=1", "X-API-Token"=>"snip"}>,
    @event_cache=#<OasAgent::Agent::EventsCache:0x00007fca26527450 @events={}, @program_root="/app">,
    @rails_env="production",
    @rails_root="/app",
    @report_queue=#<Thread::SizedQueue:0x00007fca276fcd88>,
    @reporter_thread=#<Proc:0x00007fca276fca68 /app/vendor/bundle/ruby/3.3.0/bundler/gems/oas_agent-0863a2ae5243/lib/agent/reporter.rb:50>>>]

Check it's there:

irb(main):010> ActiveSupport::Deprecation.behavior 
=> 
[#<Proc:0x00007fca276f3ee0 /app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.2/lib/active_support/deprecation/behaviors.rb:135 (lambda)>,
 #<OasAgent::Agent::Receiver:0x00007fca276fc8d8
  @rails_root="/app",
  @rails_version="7.1.2",
  @reporter=
   #<OasAgent::Agent::Reporter:0x00007fca2760cea0
    @connection=
     #<OasAgent::Agent::Connection:0x00007fca2651f278
      @conn=#<Net::HTTP ownandship.io:443 open=true>,
      @default_headers={"Content-Encoding"=>"identity", "Host"=>"ownandship.io", "Accept"=>"text/plain; api_version=1", "X-API-Token"=>"snip"}>,
    @event_cache=
     #<OasAgent::Agent::EventsCache:0x00007fca26527450
      @events=
       {"ab8b395ea059bc7b1ae457bbc0f540b78bf33bb350f682491d4b4ecbc23b33f4"=>
         #<OasAgent::Agent::EventCache:0x00007fca23a6ac80
          @event_data=
           ["ab8b395ea059bc7b1ae457bbc0f540b78bf33bb350f682491d4b4ecbc23b33f4",
            "Calling behavior on ActiveSupport::Deprecation is deprecated and will be removed from Rails (use Rails.application.deprecators[framework].behavior where framework is for example :active_record instead)",
            "rails",
            ["(irb):9:in `<main>'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb/workspace.rb:117:in `eval'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb/workspace.rb:117:in `evaluate'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb/context.rb:566:in `evaluate'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1023:in `block (2 levels) in eval_input'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1335:in `signal_status'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1016:in `block in eval_input'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1098:in `block in each_top_level_statement'",
             "<internal:kernel>:187:in `loop'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1093:in `each_top_level_statement'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1015:in `eval_input'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1002:in `block in run'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1001:in `catch'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:1001:in `run'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/irb.rb:903:in `start'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/commands/console/console_command.rb:78:in `start'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/commands/console/console_command.rb:16:in `start'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/commands/console/console_command.rb:106:in `perform'",
             "/app/vendor/bundle/ruby/3.3.0/gems/thor-1.3.0/lib/thor/command.rb:28:in `run'",
             "/app/vendor/bundle/ruby/3.3.0/gems/thor-1.3.0/lib/thor/invocation.rb:127:in `invoke_command'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/command/base.rb:178:in `invoke_command'",
             "/app/vendor/bundle/ruby/3.3.0/gems/thor-1.3.0/lib/thor.rb:527:in `dispatch'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/command/base.rb:73:in `perform'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/command.rb:71:in `block in invoke'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/command.rb:149:in `with_argv'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/command.rb:69:in `invoke'",
             "/app/vendor/bundle/ruby/3.3.0/gems/railties-7.1.2/lib/rails/commands.rb:18:in `<main>'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/bundled_gems.rb:74:in `require'",
             "/app/vendor/ruby-3.3.0/lib/ruby/3.3.0/bundled_gems.rb:74:in `block (2 levels) in replace_require'",
             "/app/vendor/bundle/ruby/3.3.0/gems/bootsnap-1.17.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
             "/app/bin/rails:4:in `<main>'"],
            "7.1.2",
            "/app",
            1]>},
      @program_root="/app">,
    @rails_env="production",
    @rails_root="/app",
    @report_queue=#<Thread::SizedQueue:0x00007fca276fcd88>,
    @reporter_thread=#<Proc:0x00007fca276fca68 /app/vendor/bundle/ruby/3.3.0/bundler/gems/oas_agent-0863a2ae5243/lib/agent/reporter.rb:50>>>]

Test it again, the dep appears in the O&S app.

irb(main):013> ActiveSupport::Deprecation.new.warn "test"
DEPRECATION WARNING: test (called from <main> at /app/bin/rails:4)
=> "DEPRECATION WARNING: test (called from <main> at /app/bin/rails:4)"

[wjessop]

I wonder if the old behaviour was right:

def insert_deprecation_behaviour
  ActiveSupport::Deprecation.behavior << OasAgent::AgentContext.agent.receiver
end

and we just need to hook after active_support.deprecation_behavior has run, or make sure that we add to app.config.active_support.deprecation early (lib/active_support/railtie.rb):

    initializer "active_support.deprecation_behavior" do |app|
      if deprecation = app.config.active_support.deprecation
        ActiveSupport::Deprecation.behavior = deprecation
      end

      if disallowed_deprecation = app.config.active_support.disallowed_deprecation
        ActiveSupport::Deprecation.disallowed_behavior = disallowed_deprecation
      end

      if disallowed_warnings = app.config.active_support.disallowed_deprecation_warnings
        ActiveSupport::Deprecation.disallowed_warnings = disallowed_warnings
      end
    end