Bug 1571907 - Passenger threads throwing tracebacks on API jobs after spawning
Summary: Passenger threads throwing tracebacks on API jobs after spawning
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Infrastructure
Version: 6.3.1
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: 6.8.0
Assignee: satellite6-bugs
QA Contact: Lukas Pramuk
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-04-25 16:29 UTC by Craig Donnelly
Modified: 2020-10-27 12:57 UTC (History)
6 users (show)

Fixed In Version: foreman-2.1.0-0
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-10-27 12:57:24 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 2184801 0 None None None 2018-06-18 10:25:58 UTC
Red Hat Product Errata RHSA-2020:4366 0 None None None 2020-10-27 12:57:42 UTC

Description Craig Donnelly 2018-04-25 16:29:24 UTC
Description of problem:
Anytime we spawn a new passenger thread, once it processes a job for an API call (such has `hammer host list` or even actions in the WebUI such as logging in / loading the hosts page) the thread will throw a large traceback in the apache error_log.

Version-Release number of selected component (if applicable):
6.3.1

How reproducible:
100% with fresh satellite service restart, or fresh passenger thread spawn.

Steps to Reproduce:
1. katello-service restart
2. `hammer host list` || Login UI, click Hosts -> Content Hosts
3. Review /var/log/httpd/error_log

Actual results:

[ 2018-04-25 12:23:38.6323 23358/7fa582d3a700 Pool2/Spawner.h:738 ]: [App 24537 stdout] 
[ 2018-04-25 12:24:06.0811 23358/7fa582d3a700 Pool2/SmartSpawner.h:301 ]: Preloader for /usr/share/foreman started on PID 24537, listening on unix:/var/run/rubygem-passenger/passenger.1.0.23321/generation-1/backends/preloader.24570
[ 2018-04-25 12:24:07.3004 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] Thread.exclusive is deprecated, use Mutex
[ 2018-04-25 12:24:07.3004 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-0.1.2/lib/active_record/session_store/session.rb:32:in `find_by_session_id'
[ 2018-04-25 12:24:07.3005 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-0.1.2/lib/action_dispatch/session/active_record_store.rb:66:in `block in get_session'
[ 2018-04-25 12:24:07.3005 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-0.1.2/lib/active_record/session_store/extension/logger_silencer.rb:45:in `silence_logger'
[ 2018-04-25 12:24:07.3005 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-0.1.2/lib/action_dispatch/session/active_record_store.rb:65:in `get_session'
[ 2018-04-25 12:24:07.3005 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:266:in `load_session'
[ 2018-04-25 12:24:07.3005 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/session/abstract_store.rb:43:in `block in load_session'
[ 2018-04-25 12:24:07.3015 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/session/abstract_store.rb:51:in `stale_session_check!'
[ 2018-04-25 12:24:07.3016 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/session/abstract_store.rb:43:in `load_session'
[ 2018-04-25 12:24:07.3016 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/request/session.rb:180:in `load!'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/request/session.rb:172:in `load_for_read!'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/request/session.rb:89:in `[]'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/foreman/app/controllers/api/base_controller.rb:391:in `protect_api_from_forgery?'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:432:in `block in make_lambda'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:144:in `block (2 levels) in halting_and_conditional'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:144:in `each'
[ 2018-04-25 12:24:07.3017 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:144:in `all?'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:144:in `block in halting_and_conditional'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:504:in `block in call'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:504:in `each'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:504:in `call'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/abstract_controller/callbacks.rb:19:in `process_action'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/rescue.rb:29:in `process_action'
[ 2018-04-25 12:24:07.3018 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `block in instrument'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `instrument'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/abstract_controller/base.rb:137:in `process'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionview-4.2.6/lib/action_view/rendering.rb:30:in `process'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal.rb:196:in `dispatch'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
[ 2018-04-25 12:24:07.3019 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal.rb:237:in `block in action'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/route_set.rb:43:in `serve'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/mapper.rb:49:in `serve'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/journey/router.rb:43:in `block in serve'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/journey/router.rb:30:in `each'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/journey/router.rb:30:in `serve'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/route_set.rb:817:in `call'
[ 2018-04-25 12:24:07.3020 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.6/lib/apipie/static_dispatcher.rb:65:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.6/lib/apipie/extractor/recorder.rb:136:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3021 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.6/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/etag.rb:24:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/conditionalget.rb:25:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/head.rb:13:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.64/lib/katello/params_parser_wrapper.rb:12:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
[ 2018-04-25 12:24:07.3022 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/flash.rb:260:in `call'
[ 2018-04-25 12:24:07.3023 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:225:in `context'
[ 2018-04-25 12:24:07.3023 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:220:in `call'
[ 2018-04-25 12:24:07.3023 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/cookies.rb:560:in `call'
[ 2018-04-25 12:24:07.3023 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gem
[ 2018-04-25 12:24:07.3023 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] s/gems/activerecord-4.2.6/lib/active_record/query_cache.rb:36:in `call'
[ 2018-04-25 12:24:07.3023 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
[ 2018-04-25 12:24:07.3024 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/rack/logger.rb:38:in `call_app'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/rack/logger.rb:22:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/foreman/lib/middleware/tagged_logging.rb:18:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/request_id.rb:21:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/methodoverride.rb:22:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/runtime.rb:18:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/sendfile.rb:113:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-3.4.1/lib/secure_headers/middleware.rb:12:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/engine.rb:518:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/application.rb:165:in `call'
[ 2018-04-25 12:24:07.3025 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/railtie.rb:194:in `public_send'
[ 2018-04-25 12:24:07.3026 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/railtie.rb:194:in `method_missing'
[ 2018-04-25 12:24:07.3026 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:66:in `block in call'
[ 2018-04-25 12:24:07.3026 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `each'
[ 2018-04-25 12:24:07.3026 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `call'
[ 2018-04-25 12:24:07.3026 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request'
[ 2018-04-25 12:24:07.3026 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:140:in `accept_and_process_next_request'
[ 2018-04-25 12:24:07.3027 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:108:in `main_loop'
[ 2018-04-25 12:24:07.3027 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler.rb:441:in `block (3 levels) in start_threads'
[ 2018-04-25 12:24:07.3027 23358/7fa580060700 Pool2/Implementation.cpp:1274 ]: [App 24537 stderr] /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'


Expected results:

No large tracebacks.

Additional info:
Once a thread has done this 1 to a few times, it seems to dissipate, but threads are regularly recycled and started so this error persists.

Comment 1 Craig Donnelly 2018-04-25 16:33:49 UTC
The call at the time of this traceback as seen from foreman/production.log:

2018-04-25 12:24:07 684f6de0 [app] [I] Processing by Api::V2::BookmarksController#index as JSON
2018-04-25 12:24:07 684f6de0 [app] [I]   Parameters: {"search"=>"controller=hosts", "apiv"=>"v2"}
2018-04-25 12:24:07 684f6de0 [app] [I] Current user: crag (administrator)
2018-04-25 12:24:07 684f6de0 [app] [D] Setting current user thread-local variable to crag
2018-04-25 12:24:07 684f6de0 [app] [I] Expire fragment views/tabs_and_title_records-4 (0.2ms)
2018-04-25 12:24:07 684f6de0 [app] [D] Setting current location thread-local variable to none
2018-04-25 12:24:07 684f6de0 [app] [D] Setting current organization thread-local variable to Default Organization
2018-04-25 12:24:07 684f6de0 [app] [I]   Rendered api/v2/bookmarks/index.json.rabl within api/v2/layouts/index_layout (12.1ms)
2018-04-25 12:24:07 684f6de0 [app] [D] Body: {
 |   "total": 17,
 |   "subtotal": 6,
 |   "page": 1,
 |   "per_page": 20,
 |   "search": "controller=hosts",
 |   "sort": {
 |     "by": null,
 |     "order": null
 |   },
 |   "results": [{"name":"active","controller":"hosts","query":"last_report > \"35 minutes ago\" and (status.applied > 0 or status.restarted > 0)","public":true,"id":2,"owner_id":null,"owner_type":null},{"name":"disabled","controller":"hosts","query":"status.enabled = false","public":true,"id":5,"owner_id":null,"owner_type":null},{"name":"error","controller":"hosts","query":"last_report > \"35 minutes ago\" and (status.failed > 0 or status.failed_restarts > 0 or status.skipped > 0)","public":true,"id":4,"owner_id":null,"owner_type":null},{"name":"list hypervisors","controller":"hosts","query":"hypervisor = true","public":true,"id":15,"owner_id":null,"owner_type":null},{"name":"ok hosts","controller":"hosts","query":"last_report > \"35 minutes ago\" and status.enabled = true and status.applied = 0 and status.failed = 0 and status.pending = 0","public":true,"id":6,"owner_id":null,"owner_type":null},{"name":"out of sync","controller":"hosts","query":"last_report < \"30 minutes ago\" and status.enabled = true","public":true,"id":3,"owner_id":null,"owner_type":null}]
 | }
 |
2018-04-25 12:24:07 684f6de0 [app] [I] Completed 200 OK in 98ms (Views: 21.3ms | ActiveRecord: 12.0ms)

Comment 2 Craig Donnelly 2018-04-25 16:40:37 UTC
Passenger backtraces from that time:

# passenger-status --show=backtraces
Version : 4.0.18
Date    : 2018-04-25 12:24:28 -0400
Instance: 23321
Thread 'Main thread' (0x7fa582e31780, LWP 23358):
     in 'void Server::mainLoop()' (Main.cpp:540)

Thread 'Pool event loop' (0x7fa581619700, LWP 23358):
     (empty)

Thread 'Pool garbage collector' (0x7fa582ddd700, LWP 23358):
     in 'static void Passenger::ApplicationPool2::Pool::garbageCollect(Passenger::ApplicationPool2::PoolPtr)' (Pool.h:549)

Thread 'MessageServer thread' (0x7fa582d9c700, LWP 23358):
     in 'void Passenger::MessageServer::mainLoop()' (MessageServer.h:558)

Thread 'MultiLibeio dispatcher' (0x7fa582e2f700, LWP 23358):
     (empty)

Thread 'Request event loop' (0x7fa580e18700, LWP 23358):
     (empty)

Thread 'Pool analytics collector' (0x7fa582e1e700, LWP 23358):
     in 'static void Passenger::ApplicationPool2::Pool::collectAnalytics(Passenger::ApplicationPool2::PoolPtr)' (Pool.h:682)

Thread 'PipeWatcher: PID 23574 stderr, fd 23' (0x7fa582cb8700, LWP 23573):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 23743 stdout, fd 25' (0x7fa5801fb700, LWP 23573):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 23791 stderr, fd 27' (0x7fa5800a1700, LWP 23790):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 23813 stdout, fd 21' (0x7fa580123700, LWP 23790):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 24537 stdout, fd 34' (0x7fa582cf9700, LWP 24536):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 24537 stderr, fd 35' (0x7fa580060700, LWP 24536):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 24888 stdout, fd 22' (0x7fa582d7b700, LWP 24536):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'PipeWatcher: PID 24910 stdout, fd 31' (0x7fa582d3a700, LWP 24909):
     in 'void Passenger::ApplicationPool2::PipeWatcher::threadMain()' (Implementation.cpp:1246)
     in 'static void Passenger::ApplicationPool2::PipeWatcher::threadMain(boost::shared_ptr<Passenger::ApplicationPool2::PipeWatcher>)' (Implementation.cpp:1227)

Thread 'MessageServer client thread 28' (0x7fa5800e2700, LWP 23365):
     in 'void RemoteController::processBacktraces(RemoteController::CommonClientContext&, RemoteController::SpecificContext*, const std::vector<std::basic_string<char> >&)' (Main.cpp:153)
     in 'void Passenger::MessageServer::clientHandlingMainLoop(Passenger::FileDescriptor)' (MessageServer.h:491)

Comment 6 Mike McCune 2020-03-17 15:30:08 UTC
QE requested this get verified during 6.8. We are moving to Puma during 6.8 so verification will just involve checking that there is no Passenger installed on the Satellite and the error messages as noted in this BZ.

Comment 7 Lukas Pramuk 2020-08-27 06:07:51 UTC
VERIFIED.

@Satellite 6.8.0 Snap12

by the following manual reproducer:

# rpm -qa *passenger*
<empty>

# hammer host list
...

# grep stderr /var/log/httpd/error_log
<empty>

>>> no passenger tracebacks in apache error_log

Comment 10 errata-xmlrpc 2020-10-27 12:57:24 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Important: Satellite 6.8 release), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2020:4366


Note You need to log in before you can comment on or make changes to this bug.