elastic / apm-agent-ruby

https://www.elastic.co/solutions/apm
Apache License 2.0
170 stars 132 forks source link

Occasional "`close': can't be called from trap context (ThreadError)" error #1357

Open slhck opened 1 year ago

slhck commented 1 year ago

Describe the bug

I occasionally get the following error running Rspec tests in my Rails app, after upgrading to Ruby 3.1.3 and Rails 7.0.4.2:

/usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:66: warning: Exception in finalizer #<Proc:0x0000ffff7e434918 /usr/local/bundle/gems/elastic-apm-4.6.0/lib/elastic_apm/transport/connection/proxy_pipe.rb:55>
/usr/local/bundle/gems/elastic-apm-4.6.0/lib/elastic_apm/transport/connection/proxy_pipe.rb:55:in `close': can't be called from trap context (ThreadError)
        from /usr/local/bundle/gems/elastic-apm-4.6.0/lib/elastic_apm/transport/connection/proxy_pipe.rb:55:in `block in finalize'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:66:in `method_added'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:66:in `block in generate_method'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:65:in `module_eval'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:65:in `block in generate_method'
        from /usr/local/lib/ruby/3.1.0/mutex_m.rb:79:in `synchronize'
        from /usr/local/lib/ruby/3.1.0/mutex_m.rb:79:in `mu_synchronize'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:61:in `generate_method'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:39:in `generate_relation_method'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/delegation.rb:107:in `method_missing'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/finder_methods.rb:575:in `ordered_relation'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/finder_methods.rb:541:in `find_nth_with_limit'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/associations/collection_proxy.rb:1119:in `find_nth_with_limit'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/finder_methods.rb:534:in `find_nth'
        from /usr/local/bundle/gems/activerecord-7.0.4.2/lib/active_record/relation/finder_methods.rb:146:in `first'
        from /home/surfmeterserver/spec/support/authentication_helper.rb:16:in `export_api_key_params'
        from /home/surfmeterserver/spec/requests/export_api/v1/measurements_spec.rb:71:in `block (4 levels) in <main>'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:263:in `instance_exec'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:263:in `block in run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:511:in `block in with_around_and_singleton_context_hooks'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:468:in `block in with_around_example_hooks'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:486:in `block in run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:626:in `block in run_around_example_hooks_for'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:352:in `call'
        from /usr/local/bundle/gems/rspec-rails-5.1.2/lib/rspec/rails/adapters.rb:75:in `block (2 levels) in <module:MinitestLifecycleAdapter>'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:457:in `instance_exec'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:457:in `instance_exec'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:390:in `execute_with'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:352:in `call'
        from /home/surfmeterserver/spec/rails_helper.rb:106:in `block (3 levels) in <main>'
        from /usr/local/bundle/gems/database_cleaner-core-2.0.1/lib/database_cleaner/strategy.rb:30:in `cleaning'
        from /usr/local/lib/ruby/3.1.0/forwardable.rb:238:in `cleaning'
        from /usr/local/bundle/gems/database_cleaner-core-2.0.1/lib/database_cleaner/cleaners.rb:34:in `block (2 levels) in cleaning'
        from /usr/local/bundle/gems/database_cleaner-core-2.0.1/lib/database_cleaner/cleaners.rb:35:in `cleaning'
        from /usr/local/lib/ruby/3.1.0/forwardable.rb:238:in `cleaning'
        from /home/surfmeterserver/spec/rails_helper.rb:105:in `block (2 levels) in <main>'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:457:in `instance_exec'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:457:in `instance_exec'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:390:in `execute_with'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:352:in `call'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:629:in `run_around_example_hooks_for'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/hooks.rb:486:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:468:in `with_around_example_hooks'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:511:in `with_around_and_singleton_context_hooks'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example.rb:259:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:646:in `block in run_examples'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:642:in `map'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:642:in `run_examples'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:607:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `block in run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `map'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `block in run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `map'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_group.rb:608:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:121:in `block (3 levels) in run_specs'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:121:in `map'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:121:in `block (2 levels) in run_specs'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/configuration.rb:2070:in `with_suite_hooks'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:116:in `block in run_specs'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/reporter.rb:74:in `report'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:115:in `run_specs'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:89:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:71:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:45:in `invoke'
        from /usr/local/bundle/gems/rspec-core-3.12.1/exe/rspec:4:in `<main>'
        from /usr/local/bundle/gems/spring-commands-rspec-1.0.4/lib/spring/commands/rspec.rb:18:in `load'
        from /usr/local/bundle/gems/spring-commands-rspec-1.0.4/lib/spring/commands/rspec.rb:18:in `call'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/command_wrapper.rb:38:in `call'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:217:in `block in serve'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:181:in `fork'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:181:in `serve'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:144:in `block in run'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:138:in `loop'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:138:in `run'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application/boot.rb:19:in `<top (required)>'
        from <internal:/usr/local/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
        from <internal:/usr/local/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
        from -e:1:in `<main>'

I only have the elastic-apm Gem installed and configured with capture_body: all.

The error does not happen all the time, just occasionally during the rspec runs.

Sometimes the stack trace is a different one:

/usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:189: warning: Exception in finalizer #<Proc:0x0000ffffab7af480 /usr/local/bundle/gems/elastic-apm-4.6.0/lib/elastic_apm/transport/connection/proxy_pipe.rb:55>
/usr/local/bundle/gems/elastic-apm-4.6.0/lib/elastic_apm/transport/connection/proxy_pipe.rb:55:in `close': can't be called from trap context (ThreadError)
        from /usr/local/bundle/gems/elastic-apm-4.6.0/lib/elastic_apm/transport/connection/proxy_pipe.rb:55:in `block in finalize'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:189:in `column_widths'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:178:in `block in formatted_row_from'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:177:in `each'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:177:in `each_with_index'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:177:in `each'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:177:in `map'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:177:in `formatted_row_from'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:168:in `block in formatted_value_rows'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:167:in `map'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:167:in `formatted_value_rows'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:154:in `dump'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:145:in `dump'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:43:in `dump_statuses'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:32:in `block in persist'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:25:in `open'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:25:in `persist'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/example_status_persister.rb:15:in `persist'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:203:in `persist_example_statuses'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:90:in `block in run'
        from <internal:kernel>:90:in `tap'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:89:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:71:in `run'
        from /usr/local/bundle/gems/rspec-core-3.12.1/lib/rspec/core/runner.rb:45:in `invoke'
        from /usr/local/bundle/gems/rspec-core-3.12.1/exe/rspec:4:in `<main>'
        from /usr/local/bundle/gems/spring-commands-rspec-1.0.4/lib/spring/commands/rspec.rb:18:in `load'
        from /usr/local/bundle/gems/spring-commands-rspec-1.0.4/lib/spring/commands/rspec.rb:18:in `call'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/command_wrapper.rb:38:in `call'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:217:in `block in serve'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:181:in `fork'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:181:in `serve'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:144:in `block in run'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:138:in `loop'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application.rb:138:in `run'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/application/boot.rb:19:in `<top (required)>'
        from <internal:/usr/local/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
        from <internal:/usr/local/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
        from -e:1:in `<main>'

Environment

Additional context

This has worked before when I was using Ruby 3.0 and Rails 6.1.

orkhan commented 1 year ago

same thing... still...

demsullivan commented 4 months ago

Same error. We're seeing it in the logs for our Sneakers process.

OS: Linux (Docker, ruby:3.3-slim-bookworm) Ruby version: 3.3.3 Framework and version: Rails 7.0.8.4 APM Server version: 8.11.1 Agent version: 4.7.3

RogerW commented 4 months ago

I think problem in https://github.com/ruby/ruby/blob/master/doc/signals.rdoc

Also You can read https://comandeo.dev/2023/01/01/mutexes-in-finalizers.html

possible solution - monkey patch

module ElasticAPM
  module Transport
    class Connection
      # @api private
      class ProxyPipe
        class Write
          def initialize(io, compress: true)
            @io = io
            @compress = compress
            @bytes_sent = Concurrent::AtomicFixnum.new(0)
            @config = ElasticAPM.agent&.config # this is silly, fix Logging

            return unless compress

            enable_compression!
          end
        end
      end
    end
  end
end