Skip to content

SemanticLogger::Appender::Async segmentation fault #103

New issue
New issue
Closed
Closed
SemanticLogger::Appender::Async segmentation fault#103
Assignees
reidmorrison
Labels
Bug Fix
@atcruice

Description

@atcruice
atcruice
opened on Apr 3, 2018

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:

Metadata

Metadata

Assignees

Labels

Bug Fix

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions