When using ActiveSupport::Cache::MemoryStore the NewRelic RPM Gem crashes with a NotImplementedError which slows down requests

[TRex22]

Description

We have a web request which calls a service. The service module makes use of a ActiveSupport::Cache::MemoryStore. When called with the newrelic_rpm present and active it causes the Gem to raise a NotImplementedError. The effect of this is that it drastically slows down the web request. Takes about double the time to respond.

I struggled with whether this is a bug of feature request, but I feel the negative effects of the error constitutes it being a bug.

Expected Behaviour

The gem should notify in the logs that this is not supported but should fail gracefully and either still send to NewRelic or skip the send but not hold up the request.

Troubleshooting or NR Diag results

 ** [NewRelic][2023-04-13 13:13:53 +0000 web.1 (35)] INFO : Reporting to: https://rpm.newrelic.com/accounts/
 ** [NewRelic][2023-04-13 13:14:53 +0000 web.1 (35)] ERROR : AgentThread Worker Loop exited with exception. Re-raising in case of interrupt.
 ** [NewRelic][2023-04-13 13:14:53 +0000 web.1 (35)] ERROR : NotImplementedError: NotImplementedError
 #<Thread:0x0000555f2c8065e8 /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/threading/agent_thread.rb:11 run> terminated with exception (report_on_exception is true):
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/encoders.rb:47:in `dump'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/encoders.rb:47:in `encode'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/transaction/trace.rb:145:in `to_collector_array'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:12:in `prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `block in prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `map'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `block in prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `map'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/json_marshaller.rb:31:in `dump'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:656:in `marshal_payload'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:544:in `invoke_remote'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:157:in `transaction_sample_data'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:114:in `send_data_to_endpoint'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:31:in `harvest_and_send_from_container'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:70:in `harvest_and_send_transaction_traces'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:105:in `harvest_and_send_data_types'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/transmit.rb:54:in `block in transmit_data'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:249:in `session_with_keepalive'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:235:in `session'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/transmit.rb:53:in `transmit_data'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:66:in `block in create_and_run_event_loop'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:150:in `block in dispatch_event'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:148:in `each'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:148:in `dispatch_event'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:113:in `run_once'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:101:in `run'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:71:in `create_and_run_event_loop'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:132:in `block (2 levels) in deferred_work!'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent.rb:551:in `disable_all_tracing'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:129:in `block in deferred_work!'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:109:in `catch_errors'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:128:in `deferred_work!'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:29:in `block in start_worker_thread'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/threading/agent_thread.rb:17:in `block in create'
 ** [NewRelic][2023-04-13 13:23:50 +0000 web.1 (35)] INFO : Starting Agent shutdown
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/encoders.rb:47:in `dump'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/encoders.rb:47:in `encode'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/transaction/trace.rb:145:in `to_collector_array'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:12:in `prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `block in prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `map'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `block in prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `map'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/marshaller.rb:14:in `prepare'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service/json_marshaller.rb:31:in `dump'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:656:in `marshal_payload'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:544:in `invoke_remote'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:157:in `transaction_sample_data'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:114:in `send_data_to_endpoint'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:31:in `harvest_and_send_from_container'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:70:in `harvest_and_send_transaction_traces'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/harvest.rb:105:in `harvest_and_send_data_types'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/transmit.rb:54:in `block in transmit_data'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:249:in `session_with_keepalive'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/new_relic_service.rb:235:in `session'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/transmit.rb:53:in `transmit_data'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:66:in `block in create_and_run_event_loop'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:150:in `block in dispatch_event'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:148:in `each'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:148:in `dispatch_event'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:113:in `run_once'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/event_loop.rb:101:in `run'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:71:in `create_and_run_event_loop'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:132:in `block (2 levels) in deferred_work!'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent.rb:551:in `disable_all_tracing'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:129:in `block in deferred_work!'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:109:in `catch_errors'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:128:in `deferred_work!'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/agent_helpers/start_worker_thread.rb:29:in `block in start_worker_thread'
  from /app/vendor/bundle/ruby/2.7.0/gems/newrelic_rpm-9.1.0/lib/new_relic/agent/threading/agent_thread.rb:17:in `block in create'

Steps to Reproduce

1. In a Rails config initializer define an InMemoryCache (for testing)

   InMemoryRailsCache = ActiveSupport::Cache::MemoryStore.new(
   expires_in: 30,
   size: 10.megabytes,
   )

2. In a Rails controller action invoke the in-memory store

   in_memory_store = InMemoryRailsCache
   in_memory_store.fetch(key.to_s, force: force) do
   'Test Data'
   end

We added a feature toggle for the in-memory cache and found the exception went away when we turned the in-memory cache off.

3. Navigate to the route which access the controller action with the NewRelic Gem activated

Your Environment

Ruby version: 2.7.7 Rails Version: 5.2.8.1 newrelic_rpm version: 9.1.0

NEW_RELIC_INSTRUMENTATION_THREAD_TRACING is set to false

Additional context

For Maintainers Only or Hero Triaging this bug

Suggested Priority (P1,P2,P3,P4,P5): Suggested T-Shirt size (S, M, L, XL, Unknown):

[workato-integration[bot]]

https://issues.newrelic.com/browse/NEWRELIC-8068

[hannahramadan]

Hi @TRex22. Thanks for sharing this issue and the steps to reproduce it. We will take a look.

In the meantime, we were wondering if you recently upgraded your Ruby agent? We added additional support for ActionCable (specifically caching-related activities #1742), in 8.16.0 and are wondering if this is related.

[TRex22]

Hi @hannahramadan we recently upgraded from 9.0.0 -> 9.1.0 but were experiencing similar issues on 9.0.0 although the Gem did seem to crash less. Was quite difficult to figure out what was going on.

[hannahramadan]

Thanks @TRex22. We're still working on the reproduction. Do you still see the error if you turn off Active Support instrumentation? You can do this by adding the following to your newrelic.yml:

disable_active_support: true

[TRex22]

Hey @hannahramadan Im currently on leave (for the next two weeks) but Ive forwarded the question to my colleague. He is working on using the In-Memory cache and could possibly try that configuration setting.

[hannahramadan]

Hi @TRex22 - have you (or your colleague) had a chance to try things out with Active Support instrumentation disabled or found any other leads on what could be causing issues?

Your stack trace points to a JSON dump operation that should work fine natively with all agent-supported Rubies (v2.4+), but unfortunately, a "not-implemented" error is happening. Any ideas on anything that could impact JSON functionality in the environment?

[hannahramadan]

@TRex22 - we're unable to reproduce the issue after setting up a Rails 5.2.8.1 and Ruby 2.7.7 app that uses the provided initializer and controller code, with combinations of static and dynamic key values and force either true or false. We're currently thinking that there must be something else (a gem in Gemfile, additional usage workflow, etc.) needed to make the repro work. If you are able to set up and share a reproduction repository, we would love to take a look.

As for the question on JSON earlier, the stack trace seems to indicate that the (built-in) Ruby JSON library reports 'dump' as not implemented. But when we do require 'json'; ::JSON.methods(false).include?(:dump) it returns true for us. We're puzzled as to why the NotImplementedError is happening when the cache store is swapped out.

I'm going to remove the bug label for now for housekeeping.

[hannahramadan]

Hi @TRex22 I'm closing this issue for now but please reopen it if there is anything we can do to help.

[TRex22]

Sorry I missed your responses ... I think because we use the gem OJ that might explain this issue. But havent confirmed. We ended up not implementing this kind of cache store and going with a different solution.