search

reidmorrison / semantic_logger

Semantic Logger is a feature rich logging framework, and replacement for existing Ruby & Rails loggers.
https://logger.rocketjob.io/
Apache License 2.0
861 stars 120 forks source link

SemanticLogger::Appender::Async segmentation fault #103

Closed atcruice closed 5 years ago

atcruice commented 6 years ago

Environment

# 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

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:

vbalazs commented 6 years ago

this also affects us, it started happening with Ruby 2.5. We use the same version of gems but unicorn appserver on Amazon Linux AMI (2017.09) and Rails 5.0.x. Not a heroku-only issue. Tests are passing also.

I started to work on a minimal example to reproduce this but so far I could not achieve it. Happens only with our app on STG/PROD environments.

ps: thanks for reporting this, I was getting crazy that I am the only one affected by this monster :D

joker-777 commented 6 years ago

We also experience the same problem and it also started with Ruby 2.5 but somehow only on our production server. We use google cloud. This is a very crucial bug!!! We also don't use puma but unicorn.

02:20:02.940 longissimus /var/log/kenhub/unicorn.log /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/async.rb:76: [BUG] Segmentation fault at 0x000000005ac32a96
02:20:02.940 longissimus /var/log/kenhub/unicorn.log ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-linux]
02:20:02.940 longissimus /var/log/kenhub/unicorn.log logfile='/var/log/kenhub/unicorn.log' message='' •••
02:20:02.940 longissimus /var/log/kenhub/unicorn.log -- Control frame information -----------------------------------------------
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0082 p:---- s:0606 e:000605 CFUNC  :push
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0081 p:0009 s:0601 e:000600 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/as
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0080 p:0024 s:0596 e:000595 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/processor.r
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0079 p:0048 s:0591 e:000590 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/logger.rb:3
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0078 p:0150 s:0583 e:000582 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:334
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0077 p:0037 s:0571 e:000570 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:84
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0076 p:0010 s:0563 e:000562 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0075 p:0060 s:0558 e:000557 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/subscriber.rb:99
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0074 p:0018 s:0548 e:000547 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/log_subscriber.rb:83
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0073 p:0012 s:0540 e:000539 METHOD /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:102
02:20:02.940 longissimus /var/log/kenhub/unicorn.log c:0072 p:0012 s:0533 e:000532 BLOCK  /var/local/kenhub/kenhub.d/2/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46 [FINISH]

-- Ruby level backtrace information ----------------------------------------
/usr/bin/unicorn_rails:23:in `<main>'
/usr/bin/unicorn_rails:23:in `load'
/var/local/kenhub/kenhub/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn_rails:209:in `<top (required)>'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142:in `start'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701:in `worker_loop'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606:in `process_client'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/railtie.rb:185:in `method_missing'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/railtie.rb:185:in `public_send'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/engine.rb:522:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-attack-5.1.0/lib/rack/attack.rb:150:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-0.10.7/lib/mini_profiler/profiler.rb:171:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/sentry-raven-2.7.2/lib/raven/integrations/rack.rb:51:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rack/middlewares.rb:45:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/sendfile.rb:111:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/executor.rb:12:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/runtime.rb:22:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/method_override.rb:22:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:194:in `tagged'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/semantic_logger.rb:379:in `named_tagged'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `block in call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/rack/logger.rb:36:in `call_app'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rails/middlewares.rb:16:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:97:in `run_callbacks'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:226:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:232:in `context'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/head.rb:12:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/conditional_get.rb:25:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/etag.rb:25:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `catch'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:36:in `block in call'
/var/local/kenhub/kenhub.d/3/lib/locale_middleware.rb:14:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:844:in `call'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `serve'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `each'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:50:in `block in serve'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:253:in `dispatch'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:189:in `dispatch'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-0.10.7/lib/mini_profiler/profiling_methods.rb:76:in `block in profile_method'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionview-5.1.5/lib/action_view/rendering.rb:30:in `process'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/abstract_controller/base.rb:124:in `process'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.5/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rails/core_extensions.rb:179:in `process_action_with_datadog'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications.rb:166:in `instrument'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:27:in `instrument'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:42:in `finish_with_state'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `finish'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `each'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `block in finish'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:102:in `finish'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/log_subscriber.rb:83:in `finish'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/subscriber.rb:99:in `finish'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger/extensions/action_controller/log_subscriber.rb:12:in `process_action'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:84:in `info'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:334:in `log_internal'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/logger.rb:38:in `log'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/processor.rb:38:in `<<'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/async.rb:76:in `log'
/var/local/kenhub/kenhub.d/3/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/async.rb:76:in `push'
gingerlime commented 6 years ago

It seems to happen after we reload our unicorn workers, so could be related to SemanticLogger.reopen that we also do on after_fork.

gingerlime commented 6 years ago

I found a bug report on ruby that seems related to what's happening to us.

It mentions the same segfault, but also another error, that I could also find in our logs [BUG] pthread_mutex_lock: Invalid argument (EINVAL)

and talks about pushing to a queue after forking, which seems to be happening here(?)

Here's a more detailed trace from our unicorn log

I, [2018-04-03T08:06:51.997618 #7723]  INFO -- : reaped #<Process::Status: pid 24861 exit 0> worker=9
I, [2018-04-03T08:06:52.098066 #7723]  INFO -- : reaped #<Process::Status: pid 24704 exit 0> worker=0
I, [2018-04-03T08:06:52.098247 #7723]  INFO -- : master complete
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/async.rb:76: [BUG] pthread_mutex_lock: Invalid argument (EINVAL)
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0082 p:---- s:0606 e:000605 CFUNC  :push
c:0081 p:0009 s:0601 e:000600 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/as
c:0080 p:0024 s:0596 e:000595 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/processor.r
c:0079 p:0048 s:0591 e:000590 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/logger.rb:3
c:0078 p:0150 s:0583 e:000582 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:334
c:0077 p:0037 s:0571 e:000570 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:84
c:0076 p:0010 s:0563 e:000562 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger
c:0075 p:0060 s:0558 e:000557 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/subscriber.rb:99
c:0074 p:0018 s:0548 e:000547 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/log_subscriber.rb:83
c:0073 p:0012 s:0540 e:000539 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:102
c:0072 p:0012 s:0533 e:000532 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46 [FINISH]
c:0071 p:---- s:0529 e:000528 CFUNC  :each
c:0070 p:0014 s:0525 e:000524 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46
c:0069 p:0015 s:0517 e:000516 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb
c:0068 p:0029 s:0510 e:000508 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb
c:0067 p:0027 s:0501 e:000500 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications.rb:166
c:0066 p:0104 s:0495 e:000494 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/instrumentation.rb:30
c:0065 p:0064 s:0489 e:000488 METHOD /app/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rails/core_extensions.rb:179
c:0064 p:0132 s:0481 e:000480 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/params_wrapper.rb:252
c:0063 p:0023 s:0473 e:000472 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.5/lib/active_record/railties/controller_runtime.rb:
c:0062 p:0079 s:0467 e:000466 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/abstract_controller/base.rb:124
c:0061 p:0059 s:0460 e:000459 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionview-5.1.5/lib/action_view/rendering.rb:30
c:0060 p:0028 s:0454 e:000453 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-0.10.7/lib/mini_profiler/profiling_methods.rb:76 [FINISH]
c:0059 p:0020 s:0444 e:000443 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:189
c:0058 p:0041 s:0437 e:000436 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:253
c:0057 p:0011 s:0430 e:000429 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:49
c:0056 p:0041 s:0422 e:000421 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:31
c:0055 p:0134 s:0414 e:000413 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:50 [FINISH]
c:0054 p:---- s:0402 e:000401 CFUNC  :each
c:0053 p:0010 s:0398 e:000397 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33
c:0052 p:0041 s:0393 e:000392 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:844
c:0051 p:0164 s:0387 e:000386 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190
c:0050 p:0009 s:0381 e:000380 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168
c:0049 p:0164 s:0376 e:000375 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190
c:0048 p:0009 s:0370 e:000369 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168
c:0047 p:0164 s:0365 e:000364 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190
c:0046 p:0009 s:0359 e:000358 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168
c:0045 p:0164 s:0354 e:000353 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190
c:0044 p:0009 s:0348 e:000347 METHOD /app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168
c:0043 p:0068 s:0343 e:000342 METHOD /app/lib/locale_middleware.rb:14
c:0042 p:0009 s:0333 e:000332 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:36 [FINISH]
c:0041 p:---- s:0330 e:000329 CFUNC  :catch
c:0040 p:0061 s:0325 e:000324 METHOD /app/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:35
c:0039 p:0008 s:0319 e:000318 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/etag.rb:25
c:0038 p:0049 s:0308 e:000307 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/conditional_get.rb:25
c:0037 p:0008 s:0299 e:000298 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/head.rb:12
c:0036 p:0030 s:0291 e:000290 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:232
c:0035 p:0006 s:0280 e:000279 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:226
c:0034 p:0024 s:0275 e:000274 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/cookies.rb:613
c:0033 p:0009 s:0265 e:000264 BLOCK  /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:26
c:0032 p:0029 s:0262 e:000261 METHOD /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:97
c:0031 p:0010 s:0253 e:000252 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:24
c:0030 p:0024 s:0246 e:000245 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/debug_exceptions.rb:
c:0029 p:0008 s:0235 e:000234 METHOD /app/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rails/middlewares.rb:16
c:0028 p:0024 s:0227 e:000226 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/show_exceptions.rb:3
c:0027 p:0041 s:0220 e:000219 METHOD /app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/rack/logger.rb:36
c:0026 p:0009 s:0212 e:000211 BLOCK  /app/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger
c:0025 p:0054 s:0209 e:000208 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/semantic_lo
c:0024 p:0067 s:0204 e:000203 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:194
c:0023 p:0073 s:0196 e:000195 METHOD /app/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger
c:0022 p:0053 s:0189 e:000188 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/remote_ip.rb:79
c:0021 p:0019 s:0183 e:000182 METHOD /app/vendor/bundle/ruby/2.5.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19
c:0020 p:0039 s:0176 e:000175 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/request_id.rb:25
c:0019 p:0091 s:0170 e:000169 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/method_override.rb:22
c:0018 p:0020 s:0164 e:000163 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/runtime.rb:22
c:0017 p:0016 s:0154 e:000153 METHOD /app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/executor.rb:12
c:0016 p:0008 s:0146 e:000145 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/sendfile.rb:111
c:0015 p:0156 s:0134 e:000133 METHOD /app/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rack/middlewares.rb:45
c:0014 p:0069 s:0120 e:000119 METHOD /app/vendor/bundle/ruby/2.5.0/gems/sentry-raven-2.7.2/lib/raven/integrations/rack.rb:51
c:0013 p:0222 s:0112 e:000110 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-0.10.7/lib/mini_profiler/profiler.rb:171
c:0012 p:0115 s:0081 e:000080 METHOD /app/vendor/bundle/ruby/2.5.0/gems/rack-attack-5.1.0/lib/rack/attack.rb:150
c:0011 p:0020 s:0075 e:000074 METHOD /app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/engine.rb:522 [FINISH]
c:0010 p:---- s:0069 e:000068 CFUNC  :public_send
c:0009 p:0027 s:0063 e:000062 METHOD /app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/railtie.rb:185
c:0008 p:0017 s:0056 e:000055 METHOD /app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606
c:0007 p:0110 s:0046 E:000890 METHOD /app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701
c:0006 p:0126 s:0032 e:000031 METHOD /app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549
c:0005 p:0094 s:0024 E:000220 METHOD /app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142
c:0004 p:0232 s:0020 E:001550 TOP    /app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn_rails:209 [FINISH]
c:0003 p:---- s:0013 e:000012 CFUNC  :load
c:0002 p:0132 s:0008 E:0011c0 EVAL   /usr/bin/unicorn_rails:23 [FINISH]
c:0001 p:0000 s:0003 E:002100 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
/usr/bin/unicorn_rails:23:in `<main>'
/usr/bin/unicorn_rails:23:in `load'
/app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn_rails:209:in `<top (required)>'
/app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142:in `start'
/app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
/app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701:in `worker_loop'
/app/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606:in `process_client'
/app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/railtie.rb:185:in `method_missing'
/app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/railtie.rb:185:in `public_send'
/app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/engine.rb:522:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-attack-5.1.0/lib/rack/attack.rb:150:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-0.10.7/lib/mini_profiler/profiler.rb:171:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/sentry-raven-2.7.2/lib/raven/integrations/rack.rb:51:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rack/middlewares.rb:45:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/sendfile.rb:111:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/executor.rb:12:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/runtime.rb:22:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/method_override.rb:22:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `call'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:194:in `tagged'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/semantic_logger.rb:379:in `named_tagged'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger/extensions/rails/rack/logger.rb:19:in `block in call'
/app/vendor/bundle/ruby/2.5.0/gems/railties-5.1.5/lib/rails/rack/logger.rb:36:in `call_app'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rails/middlewares.rb:16:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:97:in `run_callbacks'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:226:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/session/abstract/id.rb:232:in `context'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/head.rb:12:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/conditional_get.rb:25:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/rack-2.0.4/lib/rack/etag.rb:25:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `catch'
/app/vendor/bundle/ruby/2.5.0/gems/warden-1.2.7/lib/warden/manager.rb:36:in `block in call'
/app/lib/locale_middleware.rb:14:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:168:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/omniauth-1.8.1/lib/omniauth/strategy.rb:190:in `call!'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:844:in `call'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `serve'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:33:in `each'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/journey/router.rb:50:in `block in serve'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:253:in `dispatch'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal.rb:189:in `dispatch'
/app/vendor/bundle/ruby/2.5.0/gems/rack-mini-profiler-0.10.7/lib/mini_profiler/profiling_methods.rb:76:in `block in profile_method'
/app/vendor/bundle/ruby/2.5.0/gems/actionview-5.1.5/lib/action_view/rendering.rb:30:in `process'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/abstract_controller/base.rb:124:in `process'
/app/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.5/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
/app/vendor/bundle/ruby/2.5.0/gems/ddtrace-0.11.3/lib/ddtrace/contrib/rails/core_extensions.rb:179:in `process_action_with_datadog'
/app/vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.5/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications.rb:166:in `instrument'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:27:in `instrument'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/instrumenter.rb:42:in `finish_with_state'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `finish'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `each'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:46:in `block in finish'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/notifications/fanout.rb:102:in `finish'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/log_subscriber.rb:83:in `finish'
/app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.5/lib/active_support/subscriber.rb:99:in `finish'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/rails_semantic_logger-fc86ef4c7c03/lib/rails_semantic_logger/extensions/action_controller/log_subscriber.rb:12:in `process_action'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:84:in `info'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/base.rb:334:in `log_internal'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/logger.rb:38:in `log'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/processor.rb:38:in `<<'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/async.rb:76:in `log'
/app/vendor/bundle/ruby/2.5.0/bundler/gems/semantic_logger-ce0cade06919/lib/semantic_logger/appender/async.rb:76:in `push'

-- C level backtrace information -------------------------------------------
/usr/bin/ruby(rb_vm_bugreport+0xcf4) [0x5635cc7d5944] vm_dump.c:703
/usr/bin/ruby(rb_bug+0xd0) [0x5635cc7c96d0] error.c:565
/usr/bin/ruby(rb_bug_errno+0x3a) [0x5635cc7c987a] error.c:594
/usr/bin/ruby(rb_threadptr_interrupt_common.constprop.78+0x5b) [0x5635cc6eea4b] thread_pthread.c:211
/usr/bin/ruby(rb_queue_push+0xd4) [0x5635cc6ef5e4] thread.c:437
/usr/bin/ruby(vm_call_cfunc+0xee) [0x5635cc727a5e] vm_insnhelper.c:1918
/usr/bin/ruby(vm_call_method+0xe3) [0x5635cc736523] vm_insnhelper.c:2381
/usr/bin/ruby(vm_exec_core+0x12f1) [0x5635cc72eb91] insns.def:1420
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(invoke_iseq_block_from_c+0x3a0) [0x5635cc735620] vm.c:979
/usr/bin/ruby(rb_yield+0xcf) [0x5635cc73d0df] vm.c:1049
/usr/bin/ruby(rb_ary_each+0x3d) [0x5635cc74dfcd] array.c:1836
/usr/bin/ruby(vm_call_cfunc+0xee) [0x5635cc727a5e] vm_insnhelper.c:1918
/usr/bin/ruby(vm_exec_core+0x3350) [0x5635cc730bf0] insns.def:850
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(invoke_bmethod.isra.123+0x1a0) [0x5635cc735170] vm.c:1000
/usr/bin/ruby(invoke_iseq_block_from_c+0x1b7) [0x5635cc735437] vm.c:1034
/usr/bin/ruby(vm_call_bmethod+0x21f) [0x5635cc735e7f] vm.c:1124
/usr/bin/ruby(vm_call_method+0xe3) [0x5635cc736523] vm_insnhelper.c:2381
/usr/bin/ruby(vm_exec_core+0x3589) [0x5635cc730e29] insns.def:915
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(invoke_iseq_block_from_c+0x3a0) [0x5635cc735620] vm.c:979
/usr/bin/ruby(rb_yield+0xcf) [0x5635cc73d0df] vm.c:1049
/usr/bin/ruby(rb_ary_each+0x3d) [0x5635cc74dfcd] array.c:1836
/usr/bin/ruby(vm_call_cfunc+0xee) [0x5635cc727a5e] vm_insnhelper.c:1918
/usr/bin/ruby(vm_call_method+0xe3) [0x5635cc736523] vm_insnhelper.c:2381
/usr/bin/ruby(vm_exec_core+0x3350) [0x5635cc730bf0] insns.def:850
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(invoke_iseq_block_from_c+0x3a0) [0x5635cc735620] vm.c:979
/usr/bin/ruby(catch_i+0xb2) [0x5635cc73caa2] vm.c:1049
/usr/bin/ruby(vm_catch_protect+0xa1) [0x5635cc72a371] vm_eval.c:1997
/usr/bin/ruby(rb_f_catch+0x2e) [0x5635cc72a55e] vm_eval.c:2023
/usr/bin/ruby(vm_call_cfunc+0xee) [0x5635cc727a5e] vm_insnhelper.c:1918
/usr/bin/ruby(vm_call_method+0xe3) [0x5635cc736523] vm_insnhelper.c:2381
/usr/bin/ruby(vm_exec_core+0x3350) [0x5635cc730bf0] insns.def:850
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(vm_call0_body.constprop.141+0x1b7) [0x5635cc737417] vm_eval.c:127
/usr/bin/ruby(rb_call0+0xe6) [0x5635cc737d06] vm_eval.c:58
/usr/bin/ruby(send_internal+0x10d) [0x5635cc73801d] vm_eval.c:912
/usr/bin/ruby(vm_call_cfunc+0xee) [0x5635cc727a5e] vm_insnhelper.c:1918
/usr/bin/ruby(vm_call_method+0xe3) [0x5635cc736523] vm_insnhelper.c:2381
/usr/bin/ruby(vm_exec_core+0x3350) [0x5635cc730bf0] insns.def:850
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(rb_load_internal0+0xc4) [0x5635cc60a444] load.c:611
/usr/bin/ruby(rb_f_load+0x80) [0x5635cc60aaf0] load.c:642
/usr/bin/ruby(vm_call_cfunc+0xee) [0x5635cc727a5e] vm_insnhelper.c:1918
/usr/bin/ruby(vm_call_method+0xe3) [0x5635cc736523] vm_insnhelper.c:2381
/usr/bin/ruby(vm_exec_core+0x3589) [0x5635cc730e29] insns.def:915
/usr/bin/ruby(vm_exec+0x87) [0x5635cc734877] vm.c:1778
/usr/bin/ruby(ruby_exec_internal+0xc4) [0x5635cc5bd164] eval.c:246
/usr/bin/ruby(ruby_run_node+0x2f) [0x5635cc5c179f] eval.c:310
/usr/bin/ruby(main+0x4b) [0x5635cc5bcc0b] ./include/ruby/intern.h:295
reidmorrison commented 6 years ago

I do recall seeing concurrency segfaults when we first tried to move to Ruby 2.5.0, but those were fixed with Ruby 2.5.1. Some of the stack traces above show Ruby 2.5.0, maybe Ruby 2.5.1 could help with those? For those already on 2.5.1, reverting to Ruby 2.4 may be the only option until Ruby 2.5.2 is made available.

gingerlime commented 6 years ago

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.

jeffjo commented 6 years ago

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

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?

nathantsoi commented 6 years ago

I'm seeing the same issue w/ 4.2.2, ruby 2.5.1, passenger 5.2.3, and nginx 1.13.11

nathantsoi commented 6 years ago

adding the following in an initializer, as suggested by @jeffjo, seems to work. did you notice any other side effects @jeffjo?

if defined?(PhusionPassenger)
  PhusionPassenger.on_event(:starting_worker_process) do |forked|
    if forked
      SemanticLogger::Processor.instance_variable_set(:@processor, SemanticLogger::Processor.send(:create_instance))
      SemanticLogger.reopen
    end
  end
end
jeffjo commented 6 years ago

We haven't noticed any, but I would like @reidmorrison to chime in to see if there's a cleaner way to achieve the same result.

reidmorrison commented 6 years ago

This is clearly a bug with Ruby 2.5.0 and 2.5.1 since calling @thread&.alive? after a process fork should not cause MRI to crash, it should return false. As a workaround I can change SemanticLogger.reopen to always create a new thread. The risk with this change is that every time SemanticLogger.reopen is called it will create a new thread. It cannot kill an active thread since it cannot check if the thread is running without MRI crashing after a fork.

reidmorrison commented 6 years ago

Actually if someone wants to try something to see if it is the thread or the queue that is causing MRI to crash, try the following and let us know if MRI still crashes:

if defined?(PhusionPassenger)
  PhusionPassenger.on_event(:starting_worker_process) do |forked|
    if forked
      SemanticLogger::Processor.instance.instance_variable_set(:@queue, Queue.new)
      SemanticLogger.reopen
    end
  end
end
dkamenka commented 6 years ago

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

bayprogrammer commented 6 years ago

@reidmorrison Reinstantiating the Queue instance before reopening with Puma's on_worker_boot setup block fixes the issue for me. Using Ruby 2.5.1, Puma 3.11.4, and Semantic Logger 4.3.0 in this case. Without resetting the @queue variable I get segfaults similar to described in earlier comments.

rgaufman commented 6 years ago

Getting a segfault here on a Mac with ruby 2.5.1p57, the SemanticLogger::Processor.instance.instance_variable_set(:@queue, Queue.new) workaround works, thank you!

Silex commented 6 years ago

Are the ruby dev aware of this? Should the fix be done in ruby or in semantic_logger?

gingerlime commented 6 years ago

@Silex https://bugs.ruby-lang.org/issues/14634 (I mentioned this above), but it looks like there's also a way to work around it within SemanticLogger. I didn't have too much time to look into this and we simply reverted to an older ruby for now.

Silex commented 6 years ago

@gingerlime: ah thanks :+1: Sorry I thought I read it all but apparently not :smile:

ludwick commented 5 years ago

I'm testing an upgrade of our Rails stack, which uses semantic logger and Passenger, and I ran into this. I"m currently using this workaround:

`if defined?(PhusionPassenger) PhusionPassenger.on_event(:starting_worker_process) do |forked| next unless forked

SemanticLogger::Processor.instance_variable_set(:@processor, SemanticLogger::Processor.send(:create_instance))
SemanticLogger.reopen

end end Note that I had to put it in an initializer that definitely ran first (prefixed with00_`) because if any other initializer triggered logging via semantic logger, the crash would occur.

But now that it's running I sometimes see our logs and sometimes not. We have everything emit to stdout/stderr since we're in a docker-based environment (Kubernetes). At "info" log level we typically see some basic "Completed #some_route" json payloads with other information about the endpoint that was requested so it's really obvious when logs are missing.

In my case, if I restart passenger internally inside the container, the logs appear which is surprising. On other launches of the container, the logs emit fine on the first launch so it seems not a consistent issue that it stops logging.

Has anyone else seen that with this workaround? Note I've also tried it with the other workaround given that replaces the queue object. Note also that output that isn't emitted via semantic logger (e.g. our startup code and passenger stuff) shows up fine. I don't really even know where to begin since there are ... no logs!

gingerlime commented 5 years ago

I think the bug at https://bugs.ruby-lang.org/issues/14634 was closed about a month ago, so in theory ruby 2.5.2 and above shouldn't have this problem. We since switched to Puma with ruby 2.5.3 but we're using the prune_bundler option, which I think makes things a bit safer in general (and doesn't require any form of reopen etc). We haven't bumped into this problem in production.

That said, I did bump into this error once on my docker-based development environment. I'm not entirely sure how to reproduce it though...

I guess it doesn't really answer your question @ludwick, but my gut feeling is that there's still something in SemanticLogger that can be fixed/improved to avoid this, but I understand that it's a very tricky bug to reproduce, which can make any fix much harder to implement and test unfortunately.

Hope others can chime in on what works for them?

ludwick commented 5 years ago

The ruby lang bug was closed but I could find no evidence the fix was actually backported to any 2.5.x release (bug # did not show in release notes) and we're actually running 2.5.3 where I'm seeing this issue. :(

gingerlime commented 5 years ago

Oh :( I wasn't sure to be honest. It was kinda implied (or at least I thought it was). So this can also explain why I bumped into this problem on development (and I guess our Puma setup with prune_bundler "protects" us from this, but the problem is there).

Never interacted with ruby core, so I can't really say, but if there's a workaround for SemantichLogger, then would be great to have it. I'm not really sure what the canonical workaround looks like unfortunately.

Before the puma upgrade, we simply downgraded our ruby to 2.3. I guess 2.4 is also safe. Not an ideal solution, but not the worse one probably until this is resolved one way or another? (maybe in ruby 3.x hehe)

gingerlime commented 5 years ago

hmmm... I'm a bit confused though. There's a note from 6 months ago linking to this PR https://github.com/github/ruby/pull/40 which was merged...

ludwick commented 5 years ago

Commit log for release 2.5.2 of MRI: https://github.com/ruby/ruby/compare/v2_5_1...v2_5_2 I can't fine 14634 anywhere in there.

2.5.3 is just a packaging release fix and has no fixes: https://www.ruby-lang.org/en/news/2018/10/18/ruby-2-5-3-released/

So I don't think ruby bug #14634 is available in 2.5.x anywhere. It will be in 2.6.

ludwick commented 5 years ago

Anyway, I'm probably going to downgrade us to MRI 2.4.x which doesn't seem to have the crash (since I can't figure out why on 2.5.x with the reopen workaround that sometimes logging just seems to disappear).

jeffjo commented 5 years ago

fwiw, Ruby 2.6 was released a few weeks ago: https://www.ruby-lang.org/en/news/2018/12/25/ruby-2-6-0-released/

ludwick commented 5 years ago

Thanks for the reminder! I had checked the other day if one of our other dependencies had caught up and supported 2.6 as rolling forward is preferable to back in this case. If semantic logger works with 2.6 fine then that's a better route. :)

reidmorrison commented 5 years ago

@ludwick or anyone else could you give Semantic Logger master a try? I changed it to recreate the Queue when reopen is called after a fork: https://github.com/rocketjob/semantic_logger/commit/d61bef5e8e496de0768bb4b39ef01dcf2e252837

reidmorrison commented 5 years ago

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

ludwick commented 5 years ago

At least under ruby 2.5, I still get a segmentation fault on startup (passenger phusion, etc. -- sadly there's no ruby 2.6 container published yet).

olivierlacan commented 5 years ago

Under Ruby 2.5.3, semantic_logger 4.4.0 fixes this issue for us with Puma 3.11.4. Thanks @reidmorrison!

foeken commented 5 years ago

We are also running into SEGFAULTs with 2.5.3 and 4.40. We are getting it at line 56 of async.rb btw.

jtara commented 5 years ago

Getting same as @foeken above, in a Sinatra app.

Line 56 of async.rb.

Occurs running on MacOS Mojave, and on IBM Cloud/Cloud Foundry/Linux.

The problem seems to move around, depending on environment. My app is unusable on MacOS, it segfaults on some logging during some database access. In Cloud Foundry environment, it seems to segfault once on startup and then seems OK, but this is not in production, and not being stressed with a lot of activity.

I recently moved from Ruby 2.5.0 to 2.5.3 because of this, but moving to 2.5.3 didn't fix it. Unfortunately, IBM Cloud currently doesn't support Ruby > 2.5.3 (though I can use an "unsupported" buildpack if need be) but still going to 2.6.3 doesn't solve it either, at least on macOS.

Was working fine until recently, unclear when this crept in. I might have updated Semantic Logger and perhaps a previous version was working. Will have to look at my repo history. Does anyone have a lower bound on version number that has this problem?

I will try some of the solutions from above and report back if anything solves it.

jtara commented 5 years ago

@reidmorrison could somebody with the authority please re-open? Myself and others are experiencing this with 4.4.0.

jtara commented 5 years ago

Edit: sorry, I saw the note stating this is no longer needed from 4.4. I am guessing that there was some change such that not only is this no longer needed, but no longer possible...

SemanticLogger::Processor.instance.instance_variable_set(:@queue, Queue.new)

and

SemanticLogger::Processor.instance_variable_set(:@processor, SemanticLogger::Processor.send(:create_instance))

both produce errors for me.

config/puma.rb:13:in `block in _load_from': undefined method `instance' for SemanticLogger::Processor:Class (NoMethodError)
Did you mean?  instance_of?
Traceback (most recent call last):
    20: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/ruby_executable_hooks:24:in `<main>'
    19: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/ruby_executable_hooks:24:in `eval'
    18: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/rackup:23:in `<main>'
    17: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/rackup:23:in `load'
    16: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/rack-2.0.7/bin/rackup:4:in `<top (required)>'
    15: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/rack-2.0.7/lib/rack/server.rb:148:in `start'
    14: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/rack-2.0.7/lib/rack/server.rb:297:in `start'
    13: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/rack/handler/puma.rb:73:in `run'
    12: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/launcher.rb:186:in `run'
    11: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:486:in `run'
    10: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:213:in `check_workers'
     9: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:135:in `spawn_workers'
     8: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:135:in `times'
     7: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:139:in `block in spawn_workers'
     6: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:139:in `fork'
     5: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:139:in `block (2 levels) in spawn_workers'
     4: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:273:in `worker'
     3: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/configuration.rb:278:in `run_hooks'
     2: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/configuration.rb:278:in `each'
     1: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/configuration.rb:278:in `block in run_hooks'
config/puma.rb:12:in `block in _load_from': undefined method `create_instance' for SemanticLogger::Processor:Class (NoMethodError)
Traceback (most recent call last):
    20: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/ruby_executable_hooks:24:in `<main>'
    19: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/ruby_executable_hooks:24:in `eval'
    18: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/rackup:23:in `<main>'
    17: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/bin/rackup:23:in `load'
    16: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/rack-2.0.7/bin/rackup:4:in `<top (required)>'
    15: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/rack-2.0.7/lib/rack/server.rb:148:in `start'
    14: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/rack-2.0.7/lib/rack/server.rb:297:in `start'
    13: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/rack/handler/puma.rb:73:in `run'
    12: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/launcher.rb:186:in `run'
    11: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:486:in `run'
    10: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:213:in `check_workers'
     9: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:135:in `spawn_workers'
     8: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:135:in `times'
     7: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:139:in `block in spawn_workers'
     6: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:139:in `fork'
     5: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:139:in `block (2 levels) in spawn_workers'
     4: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/cluster.rb:273:in `worker'
     3: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/configuration.rb:278:in `run_hooks'
     2: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/configuration.rb:278:in `each'
     1: from /Users/jon/.rvm/gems/ruby-2.5.3@sal_2_0/gems/puma-3.12.1/lib/puma/configuration.rb:278:in `block in run_hooks'
jasonroelofs commented 5 years ago

We're seeing the problem on Ruby 2.5.1 at the line @queue&.close, so I don't think the "fix" is actually covering the various ways that Ruby is bugging out.

atiftechverx commented 5 years ago

I am also getting the same error. Please help...

/gems/semantic_logger-4.5.0/lib/semantic_logger/appender/async.rb:85: [BUG] Segmentation fault at 0x00007f0c00000050 ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-linux]

jasonroelofs commented 5 years ago

For the record, we ended up moving off of any forking model and just load our workers directly (nginx passenger in this case: passenger_spawn_method direct).

ehenrik commented 4 years ago

We also experience issues with seg. faults which reference shared/bundle/ruby/2.5.0/gems/semantic_logger-4.5.0/lib/semantic_logger/appender/async.rb:56