Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1108246

Summary: Sometimes, access to console leads to 500 ISE
Product: OpenShift Container Platform Reporter: Jan Pazdziora (Red Hat) <jpazdziora>
Component: NodeAssignee: Luke Meyer <lmeyer>
Status: CLOSED DUPLICATE QA Contact: libra bugs <libra-bugs>
Severity: medium Docs Contact:
Priority: medium    
Version: 2.1.0CC: asimonel, bleanhar, charles_sheridan, erich, jokerman, jpazdziora, libra-onpremise-devel, mmccomas
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-12-11 15:18:36 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Jan Pazdziora (Red Hat) 2014-06-11 15:12:00 UTC 
Description of problem:

Sometimes after fresh OpenShift Enterprise 2.1 installation, attempt to access the console shows Internal Server Error.

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

openshift-origin-console-1.16.2.5-1.el6op.noarch

How reproducible:

Not deterministic.

Steps to Reproduce:
1. Install OpenShift Enterprise 2.1 via openshift.sh.
2. Run curl -L -s -v -u demo:changeme http://broker.example.com/

Actual results:

[...]
* Server auth using Basic with user 'demo'
> GET /console/applications HTTP/1.1
> Authorization: Basic ZGVtbzpjaGFuZ2VtZQ==
> User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.15.3 zlib/1.2.3 libidn/1.18 libssh2/1.4.2
> Host: broker.example.com
> Accept: */*
> 
< HTTP/1.1 500 
< Date: Wed, 11 Jun 2014 13:31:00 GMT
< Server: Apache/2.2.15 (Red Hat)
< X-Powered-By: Phusion Passenger (mod_rails/mod_rack) 3.0.21
< X-Request-Id: adbf50fe0671dacb9ed4623e7954f53d
< X-Runtime: 10.032483
< Cache-Control: private
< X-Rack-Cache: miss
< Content-Length: 6470
< Status: 500
< Content-Type: text/html; charset=utf-8
< Connection: close
< 
{ [data not shown]
* Closing connection #0

Expected results:

No internal server error.

Additional info:

The /var/log/openshift/console/production.log shows

2014-06-11 09:31:00.854 [INFO ] Started GET "/console" for 127.0.0.1 at 2014-06-11 09:31:00 -0400 (pid:25233)
2014-06-11 09:31:00.871 [INFO ] Processing by ConsoleIndexController#index as */* (pid:25233)
2014-06-11 09:31:00.873 [INFO ] Redirected to https://broker.example.com/console/applications (pid:25233)
2014-06-11 09:31:00.873 [INFO ] Completed 302 Found in 1ms (pid:25233)
2014-06-11 09:31:00.921 [INFO ] Started GET "/console/applications" for 127.0.0.1 at 2014-06-11 09:31:00 -0400 (pid:25233)
2014-06-11 09:31:00.923 [INFO ] Processing by ApplicationsController#index as */* (pid:25233)
2014-06-11 09:31:10.950 [ERROR] AsyncAware::ThreadTimedOut (The thread #<Thread:0x000000038f05b8 aborting> (index=1) did not complete within 10 seconds.) (pid:25233)
2014-06-11 09:31:10.951 [INFO ] Completed 500 Internal Server Error in 10027ms (pid:25233)
2014-06-11 09:31:10.954 [FATAL] AsyncAware::ThreadTimedOut (The thread #<Thread:0x0000000400d648 aborting> (index=0) did not complete within 10 seconds.):
  openshift-origin-console (1.23.4.2) app/controllers/async_aware.rb:38:in `block in join'
  openshift-origin-console (1.23.4.2) app/controllers/async_aware.rb:34:in `map'
  openshift-origin-console (1.23.4.2) app/controllers/async_aware.rb:34:in `join'
  openshift-origin-console (1.23.4.2) app/controllers/async_aware.rb:47:in `join!'
  openshift-origin-console (1.23.4.2) app/controllers/applications_controller.rb:85:in `index'
  actionpack (3.2.8) lib/action_controller/metal/implicit_render.rb:4:in `send_action'
  actionpack (3.2.8) lib/abstract_controller/base.rb:167:in `process_action'
  actionpack (3.2.8) lib/action_controller/metal/rendering.rb:10:in `process_action'
  actionpack (3.2.8) lib/abstract_controller/callbacks.rb:18:in `block in process_action'
  activesupport (3.2.8) lib/active_support/callbacks.rb:428:in `block (3 levels) in _run__2962986862992374822__process_action__3212566235849057720__callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_66'
  activesupport (3.2.8) lib/active_support/callbacks.rb:326:in `around'
  activesupport (3.2.8) lib/active_support/callbacks.rb:310:in `_callback_around_31'
  activesupport (3.2.8) lib/active_support/callbacks.rb:214:in `_conditional_callback_around_66'
  activesupport (3.2.8) lib/active_support/callbacks.rb:416:in `block (2 levels) in _run__2962986862992374822__process_action__3212566235849057720__callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_65'
  activesupport (3.2.8) lib/active_support/callbacks.rb:326:in `around'
  activesupport (3.2.8) lib/active_support/callbacks.rb:310:in `_callback_around_25'
  activesupport (3.2.8) lib/active_support/callbacks.rb:214:in `_conditional_callback_around_65'
  activesupport (3.2.8) lib/active_support/callbacks.rb:415:in `block in _run__2962986862992374822__process_action__3212566235849057720__callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_64'
  activesupport (3.2.8) lib/active_support/callbacks.rb:326:in `around'
  activesupport (3.2.8) lib/active_support/callbacks.rb:310:in `_callback_around_23'
  activesupport (3.2.8) lib/active_support/callbacks.rb:214:in `_conditional_callback_around_64'
  activesupport (3.2.8) lib/active_support/callbacks.rb:414:in `_run__2962986862992374822__process_action__3212566235849057720__callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.8) lib/abstract_controller/callbacks.rb:17:in `process_action'
  actionpack (3.2.8) lib/action_controller/metal/rescue.rb:29:in `process_action'
  actionpack (3.2.8) lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
  activesupport (3.2.8) lib/active_support/notifications.rb:123:in `block in instrument'
  activesupport (3.2.8) lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  activesupport (3.2.8) lib/active_support/notifications.rb:123:in `instrument'
  actionpack (3.2.8) lib/action_controller/metal/instrumentation.rb:29:in `process_action'
  actionpack (3.2.8) lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
  openshift-origin-console (1.23.4.2) app/models/rest_api/railties/controller_runtime.rb:12:in `process_action'
  actionpack (3.2.8) lib/abstract_controller/base.rb:121:in `process'
  actionpack (3.2.8) lib/abstract_controller/rendering.rb:45:in `process'
  actionpack (3.2.8) lib/action_controller/metal.rb:203:in `dispatch'
  actionpack (3.2.8) lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
  actionpack (3.2.8) lib/action_controller/metal.rb:246:in `block in action'
  actionpack (3.2.8) lib/action_dispatch/routing/route_set.rb:73:in `call'
  actionpack (3.2.8) lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
  actionpack (3.2.8) lib/action_dispatch/routing/route_set.rb:36:in `call'
  journey (1.0.4) lib/journey/router.rb:68:in `block in call'
  journey (1.0.4) lib/journey/router.rb:56:in `each'
  journey (1.0.4) lib/journey/router.rb:56:in `call'
  actionpack (3.2.8) lib/action_dispatch/routing/route_set.rb:600:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
  rack (1.4.1) lib/rack/etag.rb:23:in `call'
  rack (1.4.1) lib/rack/conditionalget.rb:25:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/head.rb:14:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/flash.rb:242:in `call'
  rack (1.4.1) lib/rack/session/abstract/id.rb:205:in `context'
  rack (1.4.1) lib/rack/session/abstract/id.rb:200:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/cookies.rb:339:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
  activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `_run__990141028731965291__call__3252005651584247264__callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
  activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
  activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (3.2.8) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  railties (3.2.8) lib/rails/rack/logger.rb:26:in `call_app'
  railties (3.2.8) lib/rails/rack/logger.rb:16:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/request_id.rb:22:in `call'
  rack (1.4.1) lib/rack/methodoverride.rb:21:in `call'
  rack (1.4.1) lib/rack/runtime.rb:17:in `call'
  activesupport (3.2.8) lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  rack-cache (1.2) lib/rack/cache/context.rb:136:in `forward'
  rack-cache (1.2) lib/rack/cache/context.rb:245:in `fetch'
  rack-cache (1.2) lib/rack/cache/context.rb:185:in `lookup'
  rack-cache (1.2) lib/rack/cache/context.rb:66:in `call!'
  rack-cache (1.2) lib/rack/cache/context.rb:51:in `call'
  railties (3.2.8) lib/rails/engine.rb:479:in `call'
  railties (3.2.8) lib/rails/application.rb:223:in `call'
  railties (3.2.8) lib/rails/railtie/configurable.rb:30:in `method_missing'
  passenger (3.0.21) lib/phusion_passenger/rack/request_handler.rb:97:in `process_request'
  passenger (3.0.21) lib/phusion_passenger/abstract_request_handler.rb:521:in `accept_and_process_next_request'
  passenger (3.0.21) lib/phusion_passenger/abstract_request_handler.rb:274:in `main_loop'
  passenger (3.0.21) lib/phusion_passenger/rack/application_spawner.rb:206:in `start_request_handler'
  passenger (3.0.21) lib/phusion_passenger/rack/application_spawner.rb:171:in `block in handle_spawn_application'
  passenger (3.0.21) lib/phusion_passenger/utils.rb:470:in `safe_fork'
  passenger (3.0.21) lib/phusion_passenger/rack/application_spawner.rb:166:in `handle_spawn_application'
  passenger (3.0.21) lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop'
  passenger (3.0.21) lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously'
  passenger (3.0.21) lib/phusion_passenger/abstract_server.rb:180:in `start'
  passenger (3.0.21) lib/phusion_passenger/rack/application_spawner.rb:129:in `start'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:253:in `block (2 levels) in spawn_rack_application'
  passenger (3.0.21) lib/phusion_passenger/abstract_server_collection.rb:132:in `lookup_or_add'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:246:in `block in spawn_rack_application'
  passenger (3.0.21) lib/phusion_passenger/abstract_server_collection.rb:82:in `block in synchronize'
  <internal:prelude>:10:in `synchronize'
  passenger (3.0.21) lib/phusion_passenger/abstract_server_collection.rb:79:in `synchronize'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:244:in `spawn_rack_application'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:137:in `spawn_application'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:275:in `handle_spawn_application'
  passenger (3.0.21) lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop'
  passenger (3.0.21) lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously'
  passenger (3.0.21) helper-scripts/passenger-spawn-server:102:in `<main>' (pid:25233)

It does not seem to be a fresh-start or restart issue -- even after dozen of minutes, I get the same result.
Comment 2 August Simonelli 2014-08-01 01:35:55 UTC 
I've just hit this on a 2.1 install as well on a build that's been running without issue for weeks. Broker restarts, console restarts, apache restarts and cache clearing all didn't help. Rebooting the broker seems to have fixed it.
Comment 6 Jan Pazdziora (Red Hat) 2015-01-05 12:29:31 UTC 

*** This bug has been marked as a duplicate of bug 1140289 ***