Running into transient NoMethodError errors with T.cast in production

Viewed 76

we’re running into transient NoMethodError errors in code paths using T.cast on our production services. Here are some notable facts

  • Is happening in sorbet-runtime as of version 0.5.10012
  • It only affects 1 host at a time and often happens in short spurts (ex. errors for < 10m and goes away).
  • On some of our production services, we’ll see errors daily. On others, it’ll be weekly
  • We were not seeing this error until we upgraded sorbet-runtime versions from 0.5.6001 to 0.5.9976 (2 years of changes). We were pinned on the old version until we could migrate off the now deprecated --dsl-plugins
  • Ruby version 2.7.4
  • We have disabled runtime validation in production - T::Configuration.default_checked_level = :never

What it looks like is that T::Utils.coerce(type) returns an unexpected value (not a subclass of T::Types::Base) for a short period of time, which leads to errors here when checking error_message_for_obj here: code

Recent stacktrace

NoMethodError: undefined method `valid?' for {:mode=>:compat}:Hash
  from sorbet-runtime (0.5.10012) lib/types/types/intersection.rb:33:in `block in valid?'
  from sorbet-runtime (0.5.10012) lib/types/types/intersection.rb:33:in `all?'
  from sorbet-runtime (0.5.10012) lib/types/types/intersection.rb:33:in `valid?'
  from sorbet-runtime (0.5.10012) lib/types/types/base.rb:133:in `error_message_for_obj'
  from sorbet-runtime (0.5.10012) lib/types/private/casts.rb:8:in `cast'
  from sorbet-runtime (0.5.10012) lib/types/_types.rb:133:in `cast'
  from < our code>

Where the line in our code looks like this

T.cast(self, T.all(T::Props::Serializable, Object)).as_json

I've not figured out a way to reproduce locally but I selectively enabled a debugging monkeypatch to T.cast to not raise some errors and log some more information.

# frozen_string_literal: true

module SorbetMonkeyPatches
  module TcastDebug
    module ClassMethods
      def cast(value, type, checked: true)
        super
      rescue NoMethodError => e
        Rails.logger.error(
          message: "[sorbet] - #{value.try(:class)} to #{type.try(:class)}",
          src_value: value.inspect,
          src_type: type.inspect,
          coerce_res: T::Utils.coerce(type).inspect,
        )
        value # ultimately don't want assertions from T.cast...this should return the same value unchanged
      end
    end
  end
end

if ENV["SORBET_DEBUG_UPGRADE"] == "true"
  ::T.singleton_class.prepend(SorbetMonkeyPatches::TcastDebug::ClassMethods)
end

When enabled, here are some sample log statements we see

[sorbet] - Class to Module {"src_value":"ProductsDomain::Api::LocaleCode","src_type":"T::Props::CustomType","coerce_res":"\"ssl_min_protocol_version\""}


...
[sorbet] - Class to Module {"src_value":"ProductsDomain::Api::LocaleCode","src_type":"T::Props::CustomType","coerce_res":"[\"workflow_state\", \"active\"]"}

If working correctly, I would’ve expected coerce_res to return a subclass of T::Types::Base, not random strings

My uninformed opinion is that we’re somehow corrupting the cache for coerced types introduced by this PR - https://github.com/sorbet/sorbet/pull/4397 .


The questions I have

  • Has this been seen before?
  • Any advice for how to address or how to continue debugging?
  • Ultimately we’d hope not to see errors from T.cast when runtime checks are disabled…should we override the optional checked param in the T.cast method definition?

Thanks for your help! Please let me know if you'd like any more debugging information

1 Answers

I don't know how recently you upgraded to Ruby 2.7. When we did the Ruby 2.7 upgrade in our codebase, one of the failure modes we saw frequently looked like this:

GC.compact was being called by certain low-level framework code (If memory serves, I think puma calls GC.compact if available, regardless of whether your application calls it directly anywhere. There may be others. You could grep the contents of your vendor/bundle directory and see if any gems have calls to it, if your codebase doesn't.)

The problems is then that certain Ruby gems with C extensions, especially on versions of those gems that were released before Ruby 2.7 was released, would not properly declare that certain objects needed to be pinned in memory.

This means that the Ruby VM would compact its heap, it would move values around under the hood such that what used to be a T::Types::Base suddenly became some object formerly owned by a C extension.

In the end, we played whack-a-mole trying to find the offending gem for a while before deciding to monkey patch GC.compact to be a no-op very early on in the process load time, which fixed our issues. It's possible the same thing will fix yours.

Unfortunately, I can't see any codepath through sorbet-runtime which would cause the code at lib/types/types/intersection.rb:33 to call .valid? on a Hash object, so I would be surprised if this were a Sorbet bug, but if you do manage to reproduce it, please file an issue against the Sorbet repo.

Related