semantic_logger: SemanticLogger::Appender::Async segmentation fault

Environment

ruby 2.5.1p57
semantic_logger (4.2.0)
rails (5.1.5)
puma (3.11.3)
rails_semantic_logger (4.2.0)
concurrent-ruby (1.0.5)

# config/application.rb
…
    if ENV["RAILS_LOG_TO_STDOUT"].present?
      require File.expand_path("../../lib/semantic_logger_key_value_formatter", __FILE__)
      config.semantic_logger.add_appender(io: STDOUT, formatter: SemanticLogger::Formatters::KeyValue.new)
      config.rails_semantic_logger.add_file_appender = false
    end
…

# config/puma.rb
…
if ENV.key?("PUMA_WORKERS")
  workers Integer(ENV["PUMA_WORKERS"]) # evaluates to 2
end

preload_app!

on_worker_boot do
  ActiveRecord::Base.establish_connection if defined?(ActiveRecord)
  SemanticLogger.reopen
end
…

partial stack trace, full is over 3000 lines

2018-04-03T02:11:53.360847+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/appender/async.rb:80: [BUG] Segmentation fault at 0x0000000000000050
2018-04-03T02:11:53.360860+00:00 app[web.1]: ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-linux]
2018-04-03T02:11:53.360862+00:00 app[web.1]: 
…
2018-04-03T02:11:53.371617+00:00 app[web.1]: -- Ruby level backtrace information ----------------------------------------
2018-04-03T02:11:53.371633+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/puma-3.11.3/lib/puma/thread_pool.rb:120:in `block in spawn_thread'
2018-04-03T02:11:53.371651+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/puma-3.11.3/lib/puma/server.rb:302:in `block in run'
2018-04-03T02:11:53.371673+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/puma-3.11.3/lib/puma/server.rb:438:in `process_client'
2018-04-03T02:11:53.371693+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/puma-3.11.3/lib/puma/server.rb:624:in `handle_request'
2018-04-03T02:11:53.371711+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/puma-3.11.3/lib/puma/configuration.rb:225:in `call'
2018-04-03T02:11:53.371728+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/engine.rb:522:in `call'
2018-04-03T02:11:53.371745+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/middleware.rb:77:in `call'
2018-04-03T02:11:53.371762+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371778+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/ssl.rb:66:in `call'
2018-04-03T02:11:53.371795+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371812+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/sendfile.rb:111:in `call'
2018-04-03T02:11:53.371831+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371854+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/static.rb:125:in `call'
2018-04-03T02:11:53.371873+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371889+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/executor.rb:12:in `call'
2018-04-03T02:11:53.371905+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371921+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
2018-04-03T02:11:53.371937+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371953+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/runtime.rb:22:in `call'
2018-04-03T02:11:53.371969+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.371985+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/method_override.rb:22:in `call'
2018-04-03T02:11:53.372003+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372025+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/request_id.rb:25:in `call'
2018-04-03T02:11:53.372045+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372062+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
2018-04-03T02:11:53.372079+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372096+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rails_semantic_logger-4.2.0/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `call'
2018-04-03T02:11:53.372113+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/base.rb:190:in `tagged'
2018-04-03T02:11:53.372130+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/semantic_logger.rb:299:in `fast_tag'
2018-04-03T02:11:53.372147+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rails_semantic_logger-4.2.0/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `block in call'
2018-04-03T02:11:53.372164+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/rack/logger.rb:36:in `call_app'
2018-04-03T02:11:53.372184+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372208+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
2018-04-03T02:11:53.372231+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372248+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
2018-04-03T02:11:53.372264+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372280+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/bugsnag-6.6.4/lib/bugsnag/integrations/rack.rb:46:in `call'
2018-04-03T02:11:53.372296+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372312+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
2018-04-03T02:11:53.372328+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:97:in `run_callbacks'
2018-04-03T02:11:53.372345+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
2018-04-03T02:11:53.372367+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372388+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/cookies.rb:613:in `call'
2018-04-03T02:11:53.372405+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372422+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:226:in `call'
2018-04-03T02:11:53.372439+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:232:in `context'
2018-04-03T02:11:53.372469+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372494+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/head.rb:12:in `call'
2018-04-03T02:11:53.372512+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372533+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/conditional_get.rb:25:in `call'
2018-04-03T02:11:53.372554+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372572+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/etag.rb:25:in `call'
2018-04-03T02:11:53.372588+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/skylight-1.6.0/lib/skylight/probes/middleware.rb:18:in `call'
2018-04-03T02:11:53.372604+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:844:in `call'
2018-04-03T02:11:53.372620+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `serve'
2018-04-03T02:11:53.372636+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `each'
2018-04-03T02:11:53.372652+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:50:in `block in serve'
2018-04-03T02:11:53.372668+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:31:in `serve'
2018-04-03T02:11:53.372684+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
2018-04-03T02:11:53.372704+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:253:in `dispatch'
2018-04-03T02:11:53.372729+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:189:in `dispatch'
2018-04-03T02:11:53.372748+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionview-5.1.5/lib/action_view/rendering.rb:30:in `process'
2018-04-03T02:11:53.372765+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/abstract_controller/base.rb:124:in `process'
2018-04-03T02:11:53.372782+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.5/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
2018-04-03T02:11:53.372799+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
2018-04-03T02:11:53.372817+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
2018-04-03T02:11:53.372834+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications.rb:166:in `instrument'
2018-04-03T02:11:53.372851+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:27:in `instrument'
2018-04-03T02:11:53.372871+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:42:in `finish_with_state'
2018-04-03T02:11:53.372893+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `finish'
2018-04-03T02:11:53.372911+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `each'
2018-04-03T02:11:53.372928+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `block in finish'
2018-04-03T02:11:53.372944+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:102:in `finish'
2018-04-03T02:11:53.372960+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/log_subscriber.rb:83:in `finish'
2018-04-03T02:11:53.372976+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/subscriber.rb:99:in `finish'
2018-04-03T02:11:53.372993+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/rails_semantic_logger-4.2.0/lib/rails_semantic_logger/extensions/action_controller/log_subscriber.rb:12:in `process_action'
2018-04-03T02:11:53.373009+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/base.rb:84:in `info'
2018-04-03T02:11:53.373025+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/base.rb:330:in `log_internal'
2018-04-03T02:11:53.373045+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/logger.rb:38:in `log'
2018-04-03T02:11:53.373067+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/processor.rb:38:in `<<'
2018-04-03T02:11:53.373086+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/appender/async.rb:80:in `log'
2018-04-03T02:11:53.373103+00:00 app[web.1]: /app/vendor/bundle/ruby/2.5.0/gems/semantic_logger-4.2.0/lib/semantic_logger/appender/async.rb:80:in `push'

I’ll happily provide more of the stack trace if it would help.

Expected Behavior

no seg-fault

Actual Behaviour

H12 (request timeout), H13 (connection closed without response), and R12 (exit timeout) errors on Heroku.

The seg-fault is occuring on Heroku (heroku-16 stack). To my dismay I’m unable to reproduce it outside Heroku. Our app’s test suite passes without issue locally and on CI (Debian 8). I’ve tried running the app locally (macOS 10.13.3) with environment variables to run puma in clustered mode and trigger semantic logger
RAILS_LOG_TO_STDOUT=true PUMA_WORKERS=2 overmind start -f Procfile.dev
but there’s no seg-fault.

Seeing it fail in Async, we suspected it might be related to concurrent-ruby. We’re currently running concurrent-ruby (1.0.5), but also tried a branch running concurrent-ruby HEAD on Heroku without success (still seg-faults).

Also tried forking semantic_logger, rails_semantic_logger, and concurrent-ruby to test on Travis with Ruby 2.5.1:

https://travis-ci.org/alexcruice/semantic_logger/builds/361435063 (passes)
https://travis-ci.org/alexcruice/rails_semantic_logger/builds/361435638 (fails, unrelated)
https://travis-ci.org/alexcruice/concurrent-ruby/builds/361488392 (passes)

About this issue

Original URL
State: closed
Created 6 years ago
Reactions: 7
Comments: 39 (16 by maintainers)

Most upvoted comments

@reidmorrison, SemanticLogger::Processor.instance.instance_variable_set(:@queue, Queue.new) fixes the issue.

dkamenka on May 15, 2018

Gem v4.4.0 has been published with this fix, please re-open this issue if it occurs again.

reidmorrison on Feb 3, 2019

I think I’ve tracked it down. I was able to repro in the following Dockerized environment:

Debian Stretch
MRI Ruby 2.5.1
Rails 5.2
Puma 3.8.2 (clustered mode, preloading app)

I created a new Rails app, added rails_semantic_logger, and called SemanticLogger.reopen in the on_worker_boot hook. The seg fault happens whenever requests are sent to puma or when the process exits.

Since we are preloading the app, semantic_logger gets loaded in the master puma process. That executes this line in Processor, which initializes an Async appender that initializes a Queue and starts the Queue processing thread.

Then, puma forks to start its workers. The thread that’s created in the master process likely mutates some internal state of the Queue and forking leaves the Queue in an inconsistent state. The forked worker process then seg faults when the Queue is accessed.

One solution is to stop preloading the app, but that will significantly increase the memory footprint of the service.

Another solution is to reinitialize the Async appender when the workers boot:

preload_app!
on_worker_boot do
   # Ewww
  SemanticLogger::Processor.instance_variable_set(:@processor, SemanticLogger::Processor.send(:create_instance))
  SemanticLogger.reopen
end

Disclaimer - This stops the seg faulting, but I’m still looking into what the consequences of doing this are.

An alternative that I just thought of, but haven’t explored yet is to set :require => false for rails_semantic_logger in the Gemfile, and instead require it in the on_worker_boot hook.

@reidmorrison Is there a specific reason why the Async Appender is initialized when the Processor class is loaded?

jeffjo on Apr 12, 2018

Thanks @reidmorrison. I think the original reporter used 2.5.1. Also the ruby bug that I linked to above mentions that this also happens with 2.5.1.

gingerlime on Apr 7, 2018