Description of problem: Created a rubyonrails application, met " We appear to be having technical difficulties" error. It is ok when creating rails app using git repo manually. Version-Release number of selected component (if applicable): devenv_3277 How reproducible: always Steps to Reproduce: 1.Login to openshift console 2.Try to create a ruby on rails appliation 3. Actual results: Met "We appear to be having technical difficulties" error when creating rubyonrails application from website.Log is as following: 2013-05-27 05:26:46.197 [DEBUG] OpenShift API (13.5ms) get https://localhost:443/broker/rest/domains.json [ code: 200 ] (pid:4768) 2013-05-27 05:29:46.303 [DEBUG] OpenShift API (180103.0ms) post https://localhost:443/broker/rest/domains/devtestnnn/applications.json [ ] (pid:4768) 2013-05-27 05:29:46.309 [DEBUG] Found errors on the response object: {} (pid:4768) 2013-05-27 05:29:46.310 [ERROR] Unhandled exception reference #8dcd707d778276f91b622cab6bbbc6eb: Failed. /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/lib/active_resource/persistent_connection.rb:178:in `rescue in request' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/lib/active_resource/persistent_connection.rb:145:in `request' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/lib/active_resource/persistent_connection.rb:127:in `block in post' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/lib/active_resource/persistent_connection.rb:275:in `with_auth' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/lib/active_resource/persistent_connection.rb:127:in `post' /opt/rh/ruby193/root/usr/share/gems/gems/activeresource-3.2.8/lib/active_resource/base.rb:1360:in `create' /opt/rh/ruby193/root/usr/share/gems/gems/activeresource-3.2.8/lib/active_resource/observing.rb:19:in `create_with_notifications' /opt/rh/ruby193/root/usr/share/gems/gems/activeresource-3.2.8/lib/active_resource/base.rb:1155:in `save' /opt/rh/ruby193/root/usr/share/gems/gems/activeresource-3.2.8/lib/active_resource/validations.rb:79:in `save_with_validation' /opt/rh/ruby193/root/usr/share/gems/gems/activeresource-3.2.8/lib/active_resource/observing.rb:19:in `save_with_notifications' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/app/models/rest_api/base.rb:303:in `save_with_change_tracking' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/app/controllers/applications_controller.rb:153:in `create' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/implicit_render.rb:4:in `send_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:167:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rendering.rb:10:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:18:in `block in process_action' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:428:in `block (3 levels) in _run__2396355882966017767__process_action__3488084961037132975__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_213' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_61' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_213' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:416:in `block (2 levels) in _run__2396355882966017767__process_action__3488084961037132975__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_212' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_59' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_212' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:415:in `block in _run__2396355882966017767__process_action__3488084961037132975__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_211' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_35' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_211' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:414:in `_run__2396355882966017767__process_action__3488084961037132975__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:17:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rescue.rb:29:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `block in instrument' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `instrument' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:29:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/params_wrapper.rb:207:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/app/models/rest_api/railties/controller_runtime.rb:12:in `process_action' /var/www/openshift/site/lib/streamline/railties/controller_runtime.rb:12:in `process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:121:in `process' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/rendering.rb:45:in `process' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:203:in `dispatch' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:246:in `block in action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in `dispatch' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:36:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call' /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in `each' /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:600:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-recaptcha-0.6.5/lib/rack/recaptcha.rb:50:in `_call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-recaptcha-0.6.5/lib/rack/recaptcha.rb:37:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/etag.rb:23:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/conditionalget.rb:35:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/head.rb:14:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/params_parser.rb:21:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/flash.rb:242:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/cookies.rb:339:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `_run__3509336982829256951__call__3557912030074832775__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_call_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/sendfile.rb:102:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/remote_ip.rb:31:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/rack/logger.rb:26:in `call_app' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/rack/logger.rb:16:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/request_id.rb:22:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/cache/strategy/local_cache.rb:72:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/engine.rb:479:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/application.rb:223:in `call' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/railtie/configurable.rb:30:in `method_missing' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/rack/request_handler.rb:96:in `process_request' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/abstract_request_handler.rb:517:in `accept_and_process_next_request' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/abstract_request_handler.rb:274:in `main_loop' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/rack/application_spawner.rb:206:in `start_request_handler' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/rack/application_spawner.rb:79:in `block in spawn_application' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/utils.rb:470:in `safe_fork' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/rack/application_spawner.rb:64:in `spawn_application' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/spawn_manager.rb:264:in `spawn_rack_application' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/spawn_manager.rb:137:in `spawn_application' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/spawn_manager.rb:275:in `handle_spawn_application' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/abstract_server.rb:357:in `server_main_loop' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/lib/phusion_passenger/abstract_server.rb:206:in `start_synchronously' /opt/rh/ruby193/root/usr/share/gems/gems/passenger-3.0.17/helper-scripts Expected results: The rubyonrails application should be able to create successfully. Additional info:
Same issue happens when creating application using dancer git url.
I just tested this on devenv_3278, and it worked fine. Could you verify that this is still a problem? Thank you.
One primary suspect is the timeout. Please time your application creation; if it is close to 3 minutes, it is strongly suspected to be the cause.
Also to confirm..... these both work when called from the client tools right?
Hiro, I mentioned this on the call but can you take a look at what's taking bundling so long. -Dan
By the look of the logs above (comment 1), the delta is just over 3 minutes (05:26:46.197 to 05:29:46.303).
I tried forcing timeouts at various places (build hook, inside Gemfile). While errors do occur, they are of different nature (from mcollective) and happens faster (2 minutes). If this is still a problem, can you attach the entire logs so we may have a little more information on how things fail?
Tested on devenv_3288 again, created rubyonrails and dancer application, I can only reproduce this from website, rhc does not have this issue, and the time of creating rubyonrails and dancer is about 2 minutes.
Created attachment 754773 [details] broker log I tried it again as well on devenv_3290, was redirected to "we are appear to have technial difficulties" page as well From the broker log ( attached), seems all the operations are completed successfully, only with a warn: WARN ] WARNING: Can't verify CSRF token authenticity (pid:4780) But website has some broken log, see attachment in comments below
Created attachment 754774 [details] site log Site log is attached, Part of the error is: 2013-05-30 06:24:56.582 [DEBUG] OpenShift API (180101.2ms) post https://localhost:443/broker/rest/domains/domx1/applications.json [ ] (pid:4897) 2013-05-30 06:24:56.583 [DEBUG] Found errors on the response object: {} (pid:4897) 2013-05-30 06:24:56.584 [ERROR] Unhandled exception reference #67b7282438683fa28a7556468ab59dd7: Failed.
But after a refresh of the browser, the "We appear to have technical difficulties" page get disappeared, and get back to the applications page app/console/applications successfully, and could confirm that the rails app is created successfully, the log generated by the refresh is like following, please help to check if more fix is needed to prevent the first time"We appear to have technical difficulties" page, or it's still accepted since refresh save it? Some site log after refresh: 2013-05-30 06:38:43.863 [INFO ] Rendered applications/_footer.html.haml (4.4ms)(pid:4897) 2013-05-30 06:38:43.865 [INFO ] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.9/app/views/applications/index.html.haml within layouts/console (30.1ms) (pid:4897) 2013-05-30 06:38:43.868 [INFO ] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.9/app/views/layouts/_head.html.haml (1.3ms) (pid:4897) 2013-05-30 06:38:43.869 [INFO ] Rendered layouts/console/_stylesheets.html.haml (1.3ms) (pid:4897) 2013-05-30 06:38:43.874 [INFO ] Rendered layouts/console/_header.html.haml (4.0ms) (pid:4897) 2013-05-30 06:38:43.876 [INFO ] Rendered layouts/_footer.html.haml (1.3ms) (pid:4897) 2013-05-30 06:38:43.877 [INFO ] Rendered layouts/console/_javascripts.html.haml (0.6ms) (pid:4897) 2013-05-30 06:38:43.877 [INFO ] Completed 200 OK in 225ms (Views: 55.7ms | OpenShift API: 144.0ms) (pid:4897) 2013-05-30 06:38:44.567 [INFO ] Started GET "/app/status/status.js?id=outage" for 203.114.244.88 at 2013-05-30 06:38:44 -0400 (pid:4897) 2013-05-30 06:38:44.573 [DEBUG] Cookies are disabled for this request by StatusApp::IgnoredCookies (pid:4897)
Created attachment 754779 [details] whole broker log Attach the whole broker log if needed.
Created attachment 754781 [details] whole site log Attach whole website log
The error is coming from here: https://github.com/openshift/origin-server/blob/rubygem-openshift-origin-console-1.9.9-1/console/lib/active_resource/persistent_connection.rb#L178 This suggests that the real error comes from Net::HTTP::Persistent::Error, but https://github.com/drbrain/net-http-persistent/blob/v2.8/lib/net/http/persistent.rb does not suggest an error the message of which is simply "Failed.". To get more information out of the problem you are seeing, I would like to get a handle on the Net::HTTP::Persistent::Error object which is presently getting swallowed by the console. Because I cannot reproduce this here, could you try commenting out lines 177 and 178 of /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-console-1.9.7/lib/active_resource/persistent_connection.rb and try again, and attach the logs here?
I was able to reproduce this on my devenv as well. Creating the app via rhc took over 3 minutes (I've done it a few times just to be sure). Here are some logs. The platform-trace.log and devenv.log are from using the web ui. The rhc.log is from running rhc with --debug. https://gist.github.com/fotioslindiakos/66f9069727f96fa1ad64 I also realized that the app is actually created and runs fine (it even shows up in my app list). So it's not the broker timing out, just the site.
It is indeed a timeout. This is what Net::HTTP::Persistent::Error looks like: https://gist.github.com/BanzaiMan/f577d844770cd9a5934d
Timeout comes from RestApi::Base. https://github.com/openshift/origin-server/blob/rubygem-openshift-origin-console-1.9.7-1/console/app/models/rest_api/base.rb#L800 Increasing the value to a larger value, say 300, fixes the problem. The output below shows a success in just over 200 seconds: 2013-05-30 21:06:16.570 [DEBUG] OpenShift API (201192.9ms) post https://localhost:443/broker/rest/domains/fooooooooooo/applications.json [ code: 201 ] (pid:13086) [6/6] 2013-05-30 21:06:16.572 [INFO ] Redirected to https://localhost/app/console/applications/rails/get_started?wizard=true (pid:13086) A couple of items to consider before proceeding: a. can we do this without ill effects on other parts of the system? b. if not, is it possible to set read_timeout for only the known slow requests?
Tested on devenv-stage_354, scalable spring application also has the time out issue when creating from website.
Temporarily fixed by increasing the web console timeout: https://github.com/openshift/origin-server/pull/2714 Next Sprint we are going to properly handle timeouts in the persistent_connection.rb and display proper error message on the web console, so I'm leaving it opened and tagging as FutureFeature.
Commit pushed to master at https://github.com/openshift/origin-server https://github.com/openshift/origin-server/commit/46090ba7b3531eeec159651c17c5a92baef62a82 Fixes Bug 967504 and Bug 969536 - increased timeout to properly handle some quickstarts
*** Bug 969536 has been marked as a duplicate of this bug. ***
Tested on devenv_3368, there is still same error when creating scalable rubyonrails and spring application.
Pull request is placed: https://github.com/openshift/origin-server/pull/2900
Commits pushed to master at https://github.com/openshift/origin-server https://github.com/openshift/origin-server/commit/94c624e6f8e78385d6422657365ab107c8ac066c Bug 967504 - web console now properly handling app creation timeout https://github.com/openshift/origin-server/commit/e684e4ad655e1981de7109586927ea0f4d5f7c4b Bug 967504 - handling timeout https://github.com/openshift/origin-server/commit/7d47a5fb61c813d2932e4b63ec0846df8d5087fb Bug 967504 - tests https://github.com/openshift/origin-server/commit/7a0672658c02005c6f93a61468e8ed95516ba7fc Bug 967504 - proper timeout
Tested on INT(devenv_3395), created scalable rubyonrails,spring and dancer, no time out issue now, so verify this bug, thanks.