Issue with running latest version 0.11.0 on Rails with puma clustered mode (killed thread rule_poller)

[LarsFronius]

Steps to reproduce:

gem install rails -v 2.5.1
rails new ~/xray-app
cd ~/xray-app
echo "gem 'aws-xray-sdk', require: ['aws-xray-sdk/facets/rails/railtie']"  >> Gemfile
bundle install
echo 'workers 2' > config/puma.rb

$ bundle exec rails server
=> Booting Puma
=> Rails 5.2.1 application starting in development
=> Run `rails server -h` for more startup options
[2204] Puma starting in cluster mode...
[2204] * Version 3.12.0 (ruby 2.5.1-p57), codename: Llamas in Pajamas
[2204] * Min threads: 0, max threads: 16
[2204] * Environment: development
[2204] * Process workers: 2
[2204] * Phased restart available
[2204] * Listening on tcp://localhost:3000
[2204] Use Ctrl-C to stop
[2204] - Worker 0 (pid: 2245) booted, phase: 0
[2204] - Worker 1 (pid: 2246) booted, phase: 0
2018-10-05 17:46:50 +0200: Rack app error handling request { GET / }
#<ThreadError: killed thread>
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/rule_poller.rb:16:in `run'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/rule_poller.rb:16:in `run'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/lead_poller.rb:24:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:33:in `block in start'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:31:in `synchronize'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:31:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:43:in `sample_request?'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/facets/helper.rb:36:in `should_sample?'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/facets/rack.rb:30:in `call'
/usr/local/lib/ruby/gems/2.5.0/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/configuration.rb:225:in `call'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:658:in `handle_request'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:472:in `process_client'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:332:in `block in run'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'
2018-10-05 17:46:51 +0200: Rack app error handling request { GET /favicon.ico }
#<ThreadError: killed thread>
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/rule_poller.rb:16:in `run'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/rule_poller.rb:16:in `run'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/lead_poller.rb:24:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:33:in `block in start'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:31:in `synchronize'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:31:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/sampling/default_sampler.rb:43:in `sample_request?'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/facets/helper.rb:36:in `should_sample?'
/usr/local/lib/ruby/gems/2.5.0/gems/aws-xray-sdk-0.11.0/lib/aws-xray-sdk/facets/rack.rb:30:in `call'
/usr/local/lib/ruby/gems/2.5.0/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/configuration.rb:225:in `call'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:658:in `handle_request'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:472:in `process_client'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/server.rb:332:in `block in run'
/usr/local/lib/ruby/gems/2.5.0/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'
^C[2204] - Gracefully shutting down workers...
[2204] === puma shutdown: 2018-10-05 17:46:56 +0200 ===
[2204] - Goodbye!
Exiting

It looks like once you enable clustered mode (worker setting in Puma) the background thread for polling sampling rules is being killed unexpectedly.

[haotianw465]

Hi, thank you four reporting the issue. I'm able to reproduce this based on steps you provided.

The issue here is that when Puma forks the worker process it only duplicates the master thread itself. Any background thread that is a child of the master is not carried to the worker. I'm able to fix this and run the multi-processing normally by having the RulePoller check and create the background thread on the flight.

We will release the fix soon. Please let me know if you have any concerns.

[LarsFronius]

Hey @haotianw465, that sounds exactly like what we need 👍
Thanks for the explanation, that makes a lot of sense!

[haotianw465]

The issue is fixed in the patch release v0.11.1.

[guidocollino]

I know that the issue is closed but in my case I have version 0.11.1 and I still get the error:

app_1 | W, [2019-01-09T14:05:40.179196 #71] WARN -- : No effective centralized sampling rule match. Fallback to local rules.
app_1 | 2019-01-09 14:05:40 +0000: Rack app error handling request { GET / }
app_1 | #<XRay::SegmentNameMissingError: XRay::SegmentNameMissingError>
app_1 | /usr/local/bundle/gems/aws-xray-sdk-0.11.1/lib/aws-xray-sdk/recorder.rb:29:in begin_segment' app_1 | /usr/local/bundle/gems/aws-xray-sdk-0.11.1/lib/aws-xray-sdk/facets/rack.rb:36:in call'
app_1 | /usr/local/bundle/gems/railties-5.2.0/lib/rails/engine.rb:524:in call' app_1 | /usr/local/bundle/gems/rack-2.0.4/lib/rack/urlmap.rb:68:in block in call'
app_1 | /usr/local/bundle/gems/rack-2.0.4/lib/rack/urlmap.rb:53:in each' app_1 | /usr/local/bundle/gems/rack-2.0.4/lib/rack/urlmap.rb:53:in call'
app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/configuration.rb:225:in call' app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:632:in handle_request'
app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:446:in process_client' app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:306:in block in run'
app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/thread_pool.rb:120:in block in spawn_thread' app_1 | W, [2019-01-09T14:05:40.427971 #71] WARN -- : No effective centralized sampling rule match. Fallback to local rules. app_1 | 2019-01-09 14:05:40 +0000: Rack app error handling request { GET /favicon.ico } app_1 | #<XRay::SegmentNameMissingError: XRay::SegmentNameMissingError> app_1 | /usr/local/bundle/gems/aws-xray-sdk-0.11.1/lib/aws-xray-sdk/recorder.rb:29:in begin_segment'
app_1 | /usr/local/bundle/gems/aws-xray-sdk-0.11.1/lib/aws-xray-sdk/facets/rack.rb:36:in call' app_1 | /usr/local/bundle/gems/railties-5.2.0/lib/rails/engine.rb:524:in call'
app_1 | /usr/local/bundle/gems/rack-2.0.4/lib/rack/urlmap.rb:68:in block in call' app_1 | /usr/local/bundle/gems/rack-2.0.4/lib/rack/urlmap.rb:53:in each'
app_1 | /usr/local/bundle/gems/rack-2.0.4/lib/rack/urlmap.rb:53:in call' app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/configuration.rb:225:in call'
app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:632:in handle_request' app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:446:in process_client'
app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/server.rb:306:in block in run' app_1 | /usr/local/bundle/gems/puma-3.11.4/lib/puma/thread_pool.rb:120:in block in spawn_thread'

[haotianw465]

Hi @guidocollino you are seeing SegmentNameMissingError which is a different issue. The SDK requires you to configure a name for segment generated from serving incoming requests. See the guide for configuring rails app:

# Configure the recorder in app_root/config/initializers/aws_xray.rb
Rails.application.config.xray = {
  # default segment name generated by XRay middleware
  name: 'myrails',
  patch: %I[net_http aws_sdk],
  # record db transactions as subsegments
  active_record: true
}

Do you have name configured as shown above?