honeycombio/beeline-ruby

FrozenError when using with routing-filter gem

Closed this issue · 15 comments

dhinus commented

I added the beeline gem in my Rails 5.2 app and I'm getting the following exception only on some routes (specifically the ones requiring authentication, that should redirect to the login page).

Puma caught this error: can't modify frozen String (FrozenError)

The exception is thrown in the routing-filter gem. If I comment out this line in my config/routes.rb the exception disappears:

filter :locale, exclude: %r(/foobar/)

Full stacktrace:

Puma caught this error: can't modify frozen String (FrozenError)
vendor/bundle/ruby/2.5.0/gems/routing-filter-0.6.2/lib/routing_filter/filter.rb:22:in `sub!'
vendor/bundle/ruby/2.5.0/gems/routing-filter-0.6.2/lib/routing_filter/filter.rb:22:in `extract_segment!'
vendor/bundle/ruby/2.5.0/gems/routing-filter-0.6.2/lib/routing_filter/filters/locale.rb:55:in `around_recognize'
vendor/bundle/ruby/2.5.0/gems/routing-filter-0.6.2/lib/routing_filter/filter.rb:11:in `run'
vendor/bundle/ruby/2.5.0/gems/routing-filter-0.6.2/lib/routing_filter/chain.rb:15:in `run'
vendor/bundle/ruby/2.5.0/gems/routing-filter-0.6.2/lib/routing_filter/adapters/routers/journey.rb:7:in `find_routes'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:68:in `recognize'
vendor/bundle/ruby/2.5.0/gems/honeycomb-beeline-1.3.0/lib/honeycomb/integrations/rails.rb:28:in `block in add_package_information'
vendor/bundle/ruby/2.5.0/gems/honeycomb-beeline-1.3.0/lib/honeycomb/integrations/rails.rb:14:in `tap'
vendor/bundle/ruby/2.5.0/gems/honeycomb-beeline-1.3.0/lib/honeycomb/integrations/rails.rb:14:in `add_package_information'
vendor/bundle/ruby/2.5.0/gems/honeycomb-beeline-1.3.0/lib/honeycomb/integrations/rack.rb:40:in `block in call'
vendor/bundle/ruby/2.5.0/gems/honeycomb-beeline-1.3.0/lib/honeycomb/client.rb:54:in `start_span'
vendor/bundle/ruby/2.5.0/gems/honeycomb-beeline-1.3.0/lib/honeycomb/integrations/rack.rb:29:in `call'
vendor/bundle/ruby/2.5.0/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
(...internal files from my app...)
vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.8/lib/rack/method_override.rb:22:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.8/lib/rack/runtime.rb:22:in `call'
vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
vendor/bundle/ruby/2.5.0/bundler/gems/rack-mini-profiler-d1dc6a4b2d18/lib/mini_profiler/profiler.rb:285:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.8/lib/rack/deflater.rb:34:in `call'
(...internal files from my app...)
vendor/bundle/ruby/2.5.0/gems/rack-protection-maximum_cookie-0.4.2/lib/rack/protection/maximum_cookie.rb:92:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.8/lib/rack/sendfile.rb:111:in `call'
vendor/bundle/ruby/2.5.0/gems/honeybadger-4.5.1/lib/honeybadger/rack/error_notifier.rb:33:in `block in call'
vendor/bundle/ruby/2.5.0/gems/honeybadger-4.5.1/lib/honeybadger/agent.rb:396:in `with_rack_env'
vendor/bundle/ruby/2.5.0/gems/honeybadger-4.5.1/lib/honeybadger/rack/error_notifier.rb:30:in `call'
vendor/bundle/ruby/2.5.0/gems/honeybadger-4.5.1/lib/honeybadger/rack/user_feedback.rb:31:in `call'
vendor/bundle/ruby/2.5.0/gems/honeybadger-4.5.1/lib/honeybadger/rack/user_informer.rb:21:in `call'
vendor/bundle/ruby/2.5.0/gems/webpacker-4.0.7/lib/webpacker/dev_server_proxy.rb:29:in `perform_request'
vendor/bundle/ruby/2.5.0/gems/rack-proxy-0.6.5/lib/rack/proxy.rb:57:in `call'
vendor/bundle/ruby/2.5.0/gems/railties-5.2.2.1/lib/rails/engine.rb:524:in `call'
vendor/bundle/ruby/2.5.0/gems/puma-3.12.2/lib/puma/configuration.rb:227:in `call'
vendor/bundle/ruby/2.5.0/gems/puma-3.12.2/lib/puma/server.rb:674:in `handle_request'
vendor/bundle/ruby/2.5.0/gems/puma-3.12.2/lib/puma/server.rb:476:in `process_client'
vendor/bundle/ruby/2.5.0/gems/puma-3.12.2/lib/puma/server.rb:334:in `block in run'
vendor/bundle/ruby/2.5.0/gems/puma-3.12.2/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
geoffharcourt commented

We are seeing the same exception, and saw it go away by commenting out the filter call. I've tried forking the gem and commenting out the string freezing, but haven't been able to get around the issue yet.

We're on Rails 6.0.2.1.

geoffharcourt commented

I wrote too quickly, we're seeing the issue on the same routes, points where we should be getting redirected by Devise.

In every case in our CI suite (and very briefly in the production app) where we could see this failing, the frozen string that was being acted by on the routing filter was /unauthenticated. I can't find that string in the beeline repo.

ajvondrak commented

I highly doubt the beeline is to blame. The integration works on the Rack middleware level to wrap the #call cycle in a Honeycomb span. The Rack env itself remains unaltered.

The relevant flow of the call stack goes like this:

So the value of path winds up being a frozen string. Where does it come from? We have to look at the aforementioned monkeypatched code.

  • path is taken from ActionDispatch::Request#path_info [ref] 
        path = env.is_a?(Hash) ? env['PATH_INFO'] : env.path_info
  • While routing-filter does keep a duplicated (unfrozen) string around... [ref] 
        original_path = path.dup
  • ...It ultimately passes the (frozen) path to the locale filter [ref] 
        @routes.filters.run(:around_recognize, path, env) do

So ActionDispatch::Request#path_info is returning a frozen string. Where does that come from?

  • ActionDispatch::Request mixes in Rack::Request::Helpers [ref]
  • Rack::Request::Helpers defines #path_info; in the latest versions of Rack, this calls #get_header [ref] 
          def path_info;       get_header(PATH_INFO).to_s                     end
  • In the latest versions, Rack::Request#get_header just looks up the key in the env hash [ref] 
          # Get a request specific value for `name`.
      def get_header(name)
        @env[name]
      end

Older versions have less indirection, but the result is the same. We look up env["PATH_INFO"] and get back a frozen string.

The beeline does not alter the env hash in any way. It's just passing the env into the ActionDispatch::Request initializer [ref]. Someone upstream from the beeline (e.g., on the puma level) is likely the culprit.

If you can locally reproduce this error consistently, you could try adding a breakpoint to the routing-filter gem. The way I'd go about it would be to bundle open routing-filter and edit the source code to add a binding.pry somewhere. Then, in the console, I'd take a look at what the value of the path is. Probably move from there further upstream to see where that frozen value is coming from.

I'd bet it's something constant being set as a default by the server, like "/". Or possibly a string literal being taken from your route configuration, assuming you have # frozen_string_literal: true in that file. It could also be lurking around somewhere else in Rails. It's a lot to comb through, though, and depends on what your whole stack looks like.

geoffharcourt commented

@ajvondrak thanks for the write-up and all the detailed digging. The string that's frozen is /unauthenticated, which I'm failing to find in our routes or the Devise or Warden gems.

I understand that beeline isn't editing the env hash, but I'm still confused as to why beeline being present changes the behavior of the app in this way. These routes and their requests succeed without beeline despite whichever middleware is responsible for the string freezing.

The two avenues I'm pursuing at this point are whether or not path can be duplicated and replaced with an unfrozen duplicate in the routing filter or where this /unauthenticated comes from. I've looked through quite a few gems including Rails, Devise, etc. and can't determine where it's being created and frozen.

geoffharcourt commented

@dhinus @ajvondrak the frozen string enters the request here:

https://github.com/wardencommunity/warden/blob/5b3cbd5bef67cbe399bb7007537bc4841bbee772/lib/warden/manager.rb#L112-L117

Commenting out the frozen string magic comment in that file allows requests to process.

  • 👍1
ajvondrak commented

Aha! Good find. 👍

Theory-crafting here: this might be triggered by the beeline specifically because it's changing the evaluation order via the middleware:

beeline-ruby/lib/honeycomb/integrations/rails.rb

Lines 38 to 42 in e165da6

class Middleware
include Rack
include Warden
include Rails
end

Here, the Warden middleware is being invoked before the Rails middleware, which winds up invoking this line:

beeline-ruby/lib/honeycomb/integrations/warden.rb

Line 33 in e165da6

env["warden"].user(scope: best_scope, run_callbacks: false).tap do |user|

This probably causes Warden to alter the request path. Then the Rails middleware triggers the routing-filter gem, which blows up on the frozen string.

I bet without the Honeycomb integration, Warden must be running some time after the ActionDispatch::Journey::Router#find_routes (which routing-filter monkeypatches). That way, routing-filter works on the unfrozen string before Warden replaces it with a frozen one.

ajvondrak commented

All told, this could arguably be fixed by routing-filter being a little less destructive on the path_info... 😇

  • 👍1
geoffharcourt commented

I think unfortunately that it needs to be destructive in order to allow for the parameters to be early in URLs without requiring every other part of the application to consider them.

It seems there are three options for applications affected by this issue:

  1. Patch routing-filter so that it doesn't extract segments from frozen paths. (This is the option I'm leaning toward.)
  2. Patch warden so that it doesn't freeze that particular string.
  3. Adjust the middleware evaluation order in beeline so that Warden's point in the processing order doesn't move.
martin308 commented

Wow such good sleuthing y'all! I think the 3rd option is not quite correct though as those include lines aren't changing the evaluation order via the middleware. Those lines are just including those modules into the middleware. The middleware itself will call the add_package_information in the rails module before the extract_user_information method from the warden module. You can see here where they are being called

beeline-ruby/lib/honeycomb/integrations/rack.rb

Line 42 in c9a3ce1

extract_user_information(env, &add_field)
.

Probably the number 3 option above should be allowing you to disable the warden integration in the same way that you can disable the other integrations. That would require some rejigging of how that code works though.

Does that sound correct?

ajvondrak commented

Patch routing-filter so that it doesn't extract segments from frozen paths. (This is the option I'm leaning toward.)

Yeah, that's what I meant before. dup the string, pass it to the segment extraction, assign the resulting string back into the env hash. Something like that.

geoffharcourt commented

I don't think duping the string works, it actually has to edit the path by extracting the filtered segments or it doesn't route correctly.

Here's what we're going to do in the interim while we're trying Honeycomb out:

module RoutingFilter
  class Filter
    def extract_segment!(pattern, path)
      if path.frozen?
        nil
      else
        path.sub!(pattern) { $2 || '' }
        path.replace('/') if path.empty?
        $1
      end
    end
  end
end
ajvondrak commented

I was thinking more like editing https://github.com/svenfuchs/routing-filter/blob/eb80b02fc916eeb9b3e490ac15e77aee0bd63539/lib/routing_filter/adapters/routers/journey.rb so it "unfreezes" the path_info string before proceeding. env["PATH_INFO"] = env["PATH_INFO"].dup. Then using String#sub! won't break downstream.

geoffharcourt commented

Yeah, that's appealing because it'll work in more cases. I don't know enough about the performance/memory impact of doubling a string on every request to be able to make that tradeoff for apps other than ours confidently.

Thanks very much for all the work you put into digging in to this and very clearly documenting your findings!

  • 👍1
geoffharcourt commented

I tried that earlier, and it makes several tests fail, as (I think?) the routing filter needs to pass on segments without the filterable segments to the rest of the app to do its route magic.

The first fix I proposed works because there's no situation where a user could pass a frozen string in as a path. This would break down if someone had a frozen-string path (maybe generated by a gem) and it had locale or other filter segments in it that weren't query params.

vreynolds commented

Hello,

We will be closing this issue as it is a low priority for us. It is unlikely that we'll ever get to it, and so we'd like to set expectations accordingly.

As we enter 2022 Q1, we are trimming our OSS backlog. This is so that we can focus better on areas that are more aligned with the OpenTelemetry-focused direction of telemetry ingest for Honeycomb.

If this issue is important to you, please feel free to ping here and we can discuss/re-open.