This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 997766 - Get "ActionController::RoutingError" in development.log when creating ruby applications
Get "ActionController::RoutingError" in development.log when creating ruby ap...
Status: CLOSED CURRENTRELEASE
Product: OpenShift Online
Classification: Red Hat
Component: Image (Show other bugs)
2.x
Unspecified Unspecified
low Severity low
: ---
: ---
Assigned To: Michal Fojtik
libra bugs
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-08-16 03:54 EDT by Zhe Wang
Modified: 2015-05-14 20:33 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-05-15 11:28:05 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Zhe Wang 2013-08-16 03:54:35 EDT
Description of problem:
When creating a ruby application (either ruby-1.8 or ruby-1.9), a fatal error will reported in development.log. However, there is no warnings in user interface about this error, and the app is accessible.

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

How reproducible:
always

Steps to Reproduce:
1. tail the development.log of broker
2. create a ruby application (either ruby-1.8 or 1.9)

Actual results:
No error was reported in CLI and the app was accessible. However, the following error were reported in the development.log of broker:

2013-08-16 03:51:15.560 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"ruby-1.9", :action=>"post-configure", :args=>{"--with-app-uuid"=>"520dd9e8fe36160aab000007", "--with-app-name"=>"rb91", "--with-container-uuid"=>"520dd9e8fe36160aab000007", "--with-container-name"=>"rb91", "--with-namespace"=>"dev3660tst", "--with-request-id"=>"575670c994b861d60524c2f51a0ea074", "--cart-name"=>"ruby-1.9", "--component-name"=>"ruby-1.9", "--with-software-version"=>"1.9", "--cartridge-vendor"=>"redhat"}}, ip-10-164-115-208, {'identity' => ip-10-164-115-208}) (Request ID: 575670c994b861d60524c2f51a0ea074) (pid:2731)
2013-08-16 03:51:18.459 [INFO ] Started GET "/" for 127.0.0.1 at 2013-08-16 03:51:18 -0400 (pid:1803)
2013-08-16 03:51:18.462 [FATAL] ActionController::RoutingError (No route matches [GET] "/"):
  actionpack (3.2.8) lib/action_dispatch/middleware/debug_exceptions.rb:21: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 (1.4.1) lib/rack/lock.rb:15:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/static.rb:62: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:79:in `block in 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:64:in `spawn_application'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:264: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:1803)
2013-08-16 03:51:18.472 [INFO ] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/templates/rescues/routing_error.erb within rescues/layout (0.7ms) (pid:1803)
2013-08-16 03:51:18.586 [INFO ] Started GET "/" for 127.0.0.1 at 2013-08-16 03:51:18 -0400 (pid:1803)
2013-08-16 03:51:18.589 [FATAL] ActionController::RoutingError (No route matches [GET] "/"):
  actionpack (3.2.8) lib/action_dispatch/middleware/debug_exceptions.rb:21: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 (1.4.1) lib/rack/lock.rb:15:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/static.rb:62: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:79:in `block in 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:64:in `spawn_application'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:264: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:1803)
2013-08-16 03:51:18.599 [INFO ] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/templates/rescues/routing_error.erb within rescues/layout (0.7ms) (pid:1803)
2013-08-16 03:51:24.126 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x0000000692ccb8 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-164-115-208", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"Starting Ruby cartridge\n", :exitcode=>0}}>] (Request ID: 575670c994b861d60524c2f51a0ea074) (pid:2731)
2013-08-16 03:51:24.130 [DEBUG] DEBUG: MCollective Response Time (execute_direct: post-configure): 8.572414868s  (Request ID: 575670c994b861d60524c2f51a0ea074) (pid:2731)

Expected results:
There should not be fatal errors when creating a ruby application.

Additional info:
Comment 1 Abhishek Gupta 2013-08-16 18:27:27 EDT
This error is expected shortly after a broker restart. Does this happen later as well?
Comment 2 Zhe Wang 2013-08-18 22:50:18 EDT
Hi, Abhishek,

First of all, this bug is reproducible in devenv_3671. Specifically, I only launched a new instance instead of restarting a broker. Moreover, I could still catch this fatal error after more than 1 hour since the instance had been ready.

Hope this info helps.

Thanks,
Zhe Wang
Comment 3 Luke Meyer 2013-08-20 16:49:56 EDT
When we were talking on the bug scrub, it was thought that this was related to PassengerPreStart.

I don't think it is. At least in my devenv,
In /var/www/openshift/broker/httpd/broker.conf I see:
 PassengerPreStart http://127.0.0.1:8080/broker/rest/api.json

However, this error would show up in the log anytime *something* hits / on the broker. Since this is reported on app creation, perhaps the passenger on *ruby apps* is configured with PassengerPreStart http://127.0.0.1:8080/ or something like that. Just my 2c
Comment 4 Luke Meyer 2013-08-20 17:22:10 EDT
I meant I don't think it's related to PassengerPreStart in the broker conf; it could definitely be related to PassengerPreStart in application conf, or something else entirely (in my test, ~/ruby/etc/conf.d/openshift.conf has "PassengerPreStart http://127.0.251.1:8080/" which shouldn't route to 127.0.0.1:8080 unless something really weird is happening). It has to be local to the broker in order to even hit / - / is not proxied to the broker. And in my test, I only saw this when the app landed on the broker.

Basically, something about ruby app creation is causing a hit to http://127.0.0.1:8080/ from the node. This doesn't cause any real problems other than this error message but for that alone it would be good to fix.
Comment 6 Abhishek Gupta 2013-09-11 13:51:38 EDT
Refer comment above. The REST calls that are resulting in this error are all invalid and attributable to user error. Marking this bug as fixed.
Comment 7 Zhe Wang 2013-09-11 22:03:50 EDT
Move the bug to verified according the Comment#5 and #6.
Comment 8 Luke Meyer 2013-09-19 13:57:19 EDT
Errors in #c5 look like something completely unrelated; probably a broken client.

The original report was this:

2013-08-16 03:51:18.459 [INFO ] Started GET "/" for 127.0.0.1 at 2013-08-16 03:51:18 -0400 (pid:1803)
2013-08-16 03:51:18.462 [FATAL] ActionController::RoutingError (No route matches [GET] "/"):

And you can recreate that just by creating a ruby app that lands on a broker-node. 

I wouldn't by any means call this an important bug. But it's still a bug.
Comment 9 Dan McPherson 2014-02-07 21:44:46 EST
Mrunal,

  It seems like PassengerSpawnIPAddress is missing at least one call to / on 127.0.0.1.
Comment 10 Mrunal Patel 2014-02-10 19:36:18 EST
Dan,
Looks like it may be the HEAD request in prespawn that still uses 127.0.0.1. I have just seen the code. I will try some experiments to find out more.
Comment 11 Dan McPherson 2014-02-10 21:56:15 EST
Mrunal, awesome... thx for looking into this one.

-Dan
Comment 12 Mrunal Patel 2014-02-11 12:50:58 EST
Verified that, that is indeed the issue. We have two options:
1. Remove PassengerPreStart from openshift.conf
2. patch prespawn (It is a one liner).

I am inclined towards option 2 to avoid migration.
Comment 13 Dan McPherson 2014-02-11 12:56:24 EST
Mrunal, We are already patching that same package right?
Comment 14 Mrunal Patel 2014-02-11 13:09:19 EST
Dan, yes, we patch the passenger package today.
Comment 15 Dan McPherson 2014-02-11 13:11:06 EST
I agree with 2 then.
Comment 16 Mrunal Patel 2014-02-13 12:58:38 EST
The new patched passenger rpm is now available in devenv.
Comment 17 Lei Zhang 2014-02-14 05:28:24 EST
Test on devenv_4375, still has such error info in development.log when create ruby-1.8 app, but no error happened when create ruby-1.9 app 


rpc_client.custom_request('cartridge_do', {:cartridge=>"ruby-1.8", :action=>"configure", :args=>{"--with-app-uuid"=>"52fdef48325b16b1550000fd", "--with-app-name"=>"myruby18", "--with-container-uuid"=>"52fdef48325b16b1550000fd", "--with-container-name"=>"myruby18", "--with-namespace"=>"omylhk", "--with-request-id"=>"5d219ac7f0d2630175256178bd5e2b61", "--component-name"=>"ruby-1.8", "--cart-name"=>"ruby-1.8", "--with-software-version"=>"1.8", "--cartridge-vendor"=>"redhat"}}, ip-10-238-145-85, {'identity' => ip-10-238-145-85}) (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:30.241 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000007bf8fb8 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-238-145-85", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0, :addtl_params=>nil}}>] (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:30.510 [DEBUG] DEBUG: MCollective Response Time (execute_direct: configure): 3.674804382s  (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:30.339 [DEBUG] DEBUG: Output of parallel execute: [{:tag=>{"op_id"=>"52fdef48325b16b155000107"}, :gear=>"52fdef48325b16b1550000fd", :job=>{:cartridge=>"openshift-origin-node", :action=>"authorized-ssh-key-batch-add", :args=>{"--with-app-uuid"=>"52fdef48325b16b1550000fd", "--with-app-name"=>"myruby18", "--with-container-uuid"=>"52fdef48325b16b1550000fd", "--with-container-name"=>"myruby18", "--with-namespace"=>"omylhk", "--with-request-id"=>"5d219ac7f0d2630175256178bd5e2b61", "--with-ssh-keys"=>[{"key"=>"AAAAB3NzaC1yc2EAAAABIwAAAQEAsqO7NgdcpSVTZC6nmsGqFnLdfEXoa+itVVC7yvPwo7MQiaoa47r8Ls5egCz3yiVJ5rwHVhHDMnn0f2tfD95sE6G+Bnxr+KvP9i2+7kx2ZUrG+wLlrbUTTgYLN4V3fOehlQSlpUuMK5M6dgO6RJH9UbFKHeRe6TU+TN5X4aBc2fDPlaUu1AeP6gsqlkF2+TUsvrh0m21VkxUawPjbE+V4E8OJlS3IvnYWkwaG3LCP+2b1KEAbKBofL/156hdJa/yquZZCxEPt3DLJM6vxIhTvYLxHpk+B+JJyzI0OY0Jy1NGLzw/HXKkBy9+g+bLRfsV4xEv6+cSVty9mF+ZASekbIQ==", "type"=>"ssh-rsa", "comment"=>"52fddf62325b16b155000001-bxtbht", "content"=>"AAAAB3NzaC1yc2EAAAABIwAAAQEAsqO7NgdcpSVTZC6nmsGqFnLdfEXoa+itVVC7yvPwo7MQiaoa47r8Ls5egCz3yiVJ5rwHVhHDMnn0f2tfD95sE6G+Bnxr+KvP9i2+7kx2ZUrG+wLlrbUTTgYLN4V3fOehlQSlpUuMK5M6dgO6RJH9UbFKHeRe6TU+TN5X4aBc2fDPlaUu1AeP6gsqlkF2+TUsvrh0m21VkxUawPjbE+V4E8OJlS3IvnYWkwaG3LCP+2b1KEAbKBofL/156hdJa/yquZZCxEPt3DLJM6vxIhTvYLxHpk+B+JJyzI0OY0Jy1NGLzw/HXKkBy9+g+bLRfsV4xEv6+cSVty9mF+ZASekbIQ=="}]}}, :result_stdout=>"", :result_stderr=>"", :result_exit_code=>0, :result_addtl_params=>nil}, {:tag=>{"op_id"=>"52fdef48325b16b155000107"}, :gear=>"52fdef48325b16b1550000fd", :job=>{:cartridge=>"openshift-origin-node", :action=>"update-configuration", :args=>{"--with-app-uuid"=>"52fdef48325b16b1550000fd", "--with-app-name"=>"myruby18", "--with-container-uuid"=>"52fdef48325b16b1550000fd", "--with-container-name"=>"myruby18", "--with-namespace"=>"omylhk", "--with-request-id"=>"5d219ac7f0d2630175256178bd5e2b61", "--with-config"=>{"auto_deploy"=>true, "deployment_branch"=>"master", "keep_deployments"=>1, "deployment_type"=>"git"}}}, :result_stdout=>"", :result_stderr=>"", :result_exit_code=>0, :result_addtl_params=>nil}, {:tag=>{"op_id"=>"52fdef48325b16b155000108"}, :gear=>"52fdef48325b16b1550000fd", :job=>{:cartridge=>"openshift-origin-node", :action=>"broker-auth-key-add", :args=>{"--with-app-uuid"=>"52fdef48325b16b1550000fd", "--with-app-name"=>"myruby18", "--with-container-uuid"=>"52fdef48325b16b1550000fd", "--with-container-name"=>"myruby18", "--with-namespace"=>"omylhk", "--with-request-id"=>"5d219ac7f0d2630175256178bd5e2b61", "--with-iv"=>"IaxhTMeqssovHzA/gYbe5Ly3Kc0ggg++7woMOJcMMgyA+bW1k1XATRdNvvXc\nM7QGaUswE12sZqQ6S431YmfitsH2ZpSy4i8xGClyfYo4Hyn3wUlh/RtZNX9L\nW3/8fVO7NOYo3NIstRKVW8lAx7uqQP1/RHX+n5pARfjPuH1/4G2xU/FOdRKn\nP1IRB08qx2VCP4zXGqeyIH/LiCBNgE3h/O1MbEUloRCv5KEOtqf8Mj7l599N\n4WjAvHxvMRTRSwn6We2oBSrVRz/rmNdo6hxGtT4R89DWjR/6oRoz/C5dwZY2\naWpc+QkS3vPdPdyp5lS/TRAEDxQRBDnVF1v4ucSFHQ==\n", "--with-token"=>"xjuS5kIGkOZJYaypsxxXbzH8vFbbZqCOGvia65VrH+GBSJoPkXI5yyyR0hxp\nTSbJvPZgsrRoIQqBwTfkjwce0oZyxl7BxWylaFqBR8VdPdQ=\n"}}, :result_stdout=>"", :result_stderr=>"", :result_exit_code=>0, :result_addtl_params=>nil}], exitcode: 0, from: ip-10-238-145-85  (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:30.340 [DEBUG] DEBUG: MCollective Response Time (execute_parallel): 332ms  (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:30.384 [DEBUG] Execute ExecuteConnectionsOp (pid:2369)
2014-02-14 05:26:30.409 [DEBUG] Execute PostConfigureCompOp comp_spec=component:ruby-1.8/ruby-1.8/52fd88b94422816bd3000020 gear_id=52fdef48325b16b1550000fd (pid:2369)
2014-02-14 05:26:30.414 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"ruby-1.8", :action=>"post-configure", :args=>{"--with-app-uuid"=>"52fdef48325b16b1550000fd", "--with-app-name"=>"myruby18", "--with-container-uuid"=>"52fdef48325b16b1550000fd", "--with-container-name"=>"myruby18", "--with-namespace"=>"omylhk", "--with-request-id"=>"5d219ac7f0d2630175256178bd5e2b61", "--component-name"=>"ruby-1.8", "--cart-name"=>"ruby-1.8", "--with-software-version"=>"1.8", "--cartridge-vendor"=>"redhat"}}, ip-10-238-145-85, {'identity' => ip-10-238-145-85}) (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:34.781 [INFO ] Started GET "/" for 127.0.0.1 at 2014-02-14 05:26:34 -0500 (pid:1930)
2014-02-14 05:26:34.783 [FATAL] ActionController::RoutingError (No route matches [GET] "/"):
  actionpack (3.2.8) lib/action_dispatch/middleware/debug_exceptions.rb:21: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 (1.4.1) lib/rack/lock.rb:15:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/static.rb:62: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:79:in `block in 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:64:in `spawn_application'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:264: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:1930)
2014-02-14 05:26:34.899 [INFO ] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/templates/rescues/routing_error.erb within rescues/layout (83.6ms) (pid:1930)
2014-02-14 05:26:40.131 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x00000007bade00 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-238-145-85", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"Starting Ruby cartridge\n", :exitcode=>0, :addtl_params=>{:deployments=>[{:id=>"154d8c2e", :ref=>"master", :sha1=>"025a7b0", :force_clean_build=>nil, :hot_deploy=>nil, :created_at=>1392373579.3049998, :activations=>[1392373592.2005167]}]}}}>] (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:40.132 [DEBUG] DEBUG: MCollective Response Time (execute_direct: post-configure): 9.719646938s  (Request ID: 5d219ac7f0d2630175256178bd5e2b61) (pid:2369)
2014-02-14 05:26:40.140 [DEBUG] Execute TrackUsageOp gear_id=52fdef48325b16b1550000fd (pid:2369)
2014-02-14 05:26:40.209 [DEBUG] SUCCESS ACTION=ADD_APPLICATION USER_ID=52fddf62325b16b155000001 LOGIN=lzhang+1@redhat.com APP_UUID=52fdef48325b16b1550000fd DOMAIN=omylhk Application myruby18 was created. (pid:2369)
2014-02-14 05:26:40.222 [INFO ] Completed 201 Created in 24228ms (Views: 11.9ms) (pid:2369)
2014-02-14 05:26:40.225 [INFO ] Started GET "/" for 127.0.0.1 at 2014-02-14 05:26:40 -0500 (pid:2369)
2014-02-14 05:26:40.228 [FATAL] ActionController::RoutingError (No route matches [GET] "/"):
  actionpack (3.2.8) lib/action_dispatch/middleware/debug_exceptions.rb:21: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 (1.4.1) lib/rack/lock.rb:15:in `call'
  actionpack (3.2.8) lib/action_dispatch/middleware/static.rb:62: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:79:in `block in 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:64:in `spawn_application'
  passenger (3.0.21) lib/phusion_passenger/spawn_manager.rb:264: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'
Comment 18 Michal Fojtik 2014-04-14 06:45:54 EDT
Tested today:

$ rhc app create rubyapp ruby-1.8

[Mon Apr 14 06:43:44 2014] [notice] Apache/2.2.15 (Unix) Phusion_Passenger/3.0.21 configured -- resuming normal operations
[rubyapp-mfojtik.dev.rhcloud.com 534bbbd7b1e718af8700006b]\> cat app-root/logs/ruby.log 
[Mon Apr 14 06:43:44 2014] [notice] SELinux policy enabled; httpd running as context unconfined_u:system_r:openshift_t:s0:c0,c1007
[Mon Apr 14 06:43:44 2014] [notice] Digest: generating secret for digest authentication ...
[Mon Apr 14 06:43:44 2014] [notice] Digest: done
[Mon Apr 14 06:43:44 2014] [notice] Apache/2.2.15 (Unix) Phusion_Passenger/3.0.21 configured -- resuming normal operations
[rubyapp-mfojtik.dev.rhcloud.com 534bbbd7b1e718af8700006b]\>

No error found.
Comment 19 Zhe Wang 2014-04-15 05:22:15 EDT
No error found in both /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/test/tmp/development.log and /var/lib/docker/containers/<uuid>/root/var/log/openshift/broker/development.log

Move this bug to VERIFIED, will reopen it if seeing this again.

2014-04-15 05:16:07.873 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"ruby-1.9", :action=>"configure", :args=>{"--with-app-uuid"=>"534cf8d11be53ae1760000aa", "--with-app-name"=>"rb91", "--with-expose-ports"=>false, "--with-container-uuid"=>"534cf8d11be53ae1760000aa", "--with-container-name"=>"rb91", "--with-namespace"=>"test", "--with-request-id"=>"8b4660554fe28fd04bdb0c9ba41f42c1", "--component-name"=>"ruby-1.9", "--cart-name"=>"ruby-1.9", "--with-software-version"=>"1.9", "--cartridge-vendor"=>"redhat"}}, ip-10-111-157-19, {'identity' => ip-10-111-157-19}) (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:10.967 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x000000076794e8 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-111-157-19", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"", :exitcode=>0, :addtl_params=>nil}}>] (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:10.985 [DEBUG] DEBUG: MCollective Response Time (execute_direct: configure): 2.229843742s  (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:10.233 [DEBUG] DEBUG: Output of parallel execute: [{:tag=>{"op_id"=>"534cf8d11be53ae1760000b4"}, :gear=>"534cf8d11be53ae1760000aa", :job=>{:cartridge=>"openshift-origin-node", :action=>"authorized-ssh-key-batch-add", :args=>{"--with-app-uuid"=>"534cf8d11be53ae1760000aa", "--with-app-name"=>"rb91", "--with-expose-ports"=>false, "--with-container-uuid"=>"534cf8d11be53ae1760000aa", "--with-container-name"=>"rb91", "--with-namespace"=>"test", "--with-request-id"=>"8b4660554fe28fd04bdb0c9ba41f42c1", "--with-ssh-keys"=>[{"key"=>"AAAAB3NzaC1yc2EAAAADAQABAAABAQDeXYx0ejOBDLWmzn+TWG8OiLCuWf3PzwYRDh9UnGIKDAkOHLfqddXtYJZ6xjbJqFSd9oB0GbIUdxEvMbxf0VJyfgtqkcrxRRBEFjneDDbT1hbh1Jm+TLdoj1D5EYBI5k7s0D3+A84duJIZmuPFt9d6CP2igQ+ellsjie+mfzIlMZE2yPrAtSuYwvxCDcmxJE54zZa7dpYWWhyawgNHEodnRAWH1iET1Qu7lRvSg/Eeo78rf4CySfplUXdchw9tUZWeK8hgzWhsS/20FbEGXC21gegZoqD/79sMTw2GA8Z17X0m5y2aE2tBPwkEl4Zc6h8Hv4QgJuLC/TE/JvVbn5uN", "type"=>"ssh-rsa", "comment"=>"534cf79d1be53ae17600008c-default", "content"=>"AAAAB3NzaC1yc2EAAAADAQABAAABAQDeXYx0ejOBDLWmzn+TWG8OiLCuWf3PzwYRDh9UnGIKDAkOHLfqddXtYJZ6xjbJqFSd9oB0GbIUdxEvMbxf0VJyfgtqkcrxRRBEFjneDDbT1hbh1Jm+TLdoj1D5EYBI5k7s0D3+A84duJIZmuPFt9d6CP2igQ+ellsjie+mfzIlMZE2yPrAtSuYwvxCDcmxJE54zZa7dpYWWhyawgNHEodnRAWH1iET1Qu7lRvSg/Eeo78rf4CySfplUXdchw9tUZWeK8hgzWhsS/20FbEGXC21gegZoqD/79sMTw2GA8Z17X0m5y2aE2tBPwkEl4Zc6h8Hv4QgJuLC/TE/JvVbn5uN"}]}}, :result_stdout=>"", :result_stderr=>"", :result_exit_code=>0, :result_addtl_params=>nil}, {:tag=>{"op_id"=>"534cf8d11be53ae1760000b4"}, :gear=>"534cf8d11be53ae1760000aa", :job=>{:cartridge=>"openshift-origin-node", :action=>"update-configuration", :args=>{"--with-app-uuid"=>"534cf8d11be53ae1760000aa", "--with-app-name"=>"rb91", "--with-expose-ports"=>false, "--with-container-uuid"=>"534cf8d11be53ae1760000aa", "--with-container-name"=>"rb91", "--with-namespace"=>"test", "--with-request-id"=>"8b4660554fe28fd04bdb0c9ba41f42c1", "--with-config"=>{"auto_deploy"=>true, "deployment_branch"=>"master", "keep_deployments"=>1, "deployment_type"=>"git"}}}, :result_stdout=>"", :result_stderr=>"", :result_exit_code=>0, :result_addtl_params=>nil}, {:tag=>{"op_id"=>"534cf8d11be53ae1760000b5"}, :gear=>"534cf8d11be53ae1760000aa", :job=>{:cartridge=>"openshift-origin-node", :action=>"broker-auth-key-add", :args=>{"--with-app-uuid"=>"534cf8d11be53ae1760000aa", "--with-app-name"=>"rb91", "--with-expose-ports"=>false, "--with-container-uuid"=>"534cf8d11be53ae1760000aa", "--with-container-name"=>"rb91", "--with-namespace"=>"test", "--with-request-id"=>"8b4660554fe28fd04bdb0c9ba41f42c1", "--with-iv"=>"ziqguzsLLeb4StRTModEHni2GoBUiscKQB7e9ib78o0cKNgJMvbzXlkaJOX6\nOX8xXkebJaTY1DhEY0SC9oTeOoBcvFCAuUAnaGEmy3IM3MlC101F7N9z/IuT\nC0qVvQl6Kwrg8XrB1sR0XT4Tm6TWIRPaKjEcCin3Mq7b+jud+GHlmdipRZ8o\nvA8k0lXdFYWoqqdEUGM43JhWeW8PazkSNDDYmwWRtrf4pdhrzcnmOPHRFUso\nBKA+agT0mSPe+HMq9It/escz2mdH+iQb2sVDf89jVxykieIAAAOf9V4mrTY2\n2v2nLaWgTQWZvYX5jZYVY+0UwOsXqsUtiLc6PQSg5w==\n", "--with-token"=>"fSwECA9InZkJPk55mC6JBS48HDsoDNFHYIm8O4qktBGe2Ekdt/s8QxXsORHq\nsjgueSWjIFZh7li2MF04NGSIBS3bRZ/CMSf8KikaJ198wBo=\n"}}, :result_stdout=>"", :result_stderr=>"", :result_exit_code=>0, :result_addtl_params=>nil}], exitcode: 0, from: ip-10-111-157-19  (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:10.281 [DEBUG] DEBUG: MCollective Response Time (execute_parallel): 181ms  (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:10.307 [DEBUG] Execute ExecuteConnectionsOp (pid:130)
2014-04-15 05:16:10.322 [DEBUG] Execute PostConfigureCompOp comp_spec=component:ruby-1.9/ruby-1.9/534c8c3aca10fe330f00001f gear_id=534cf8d11be53ae1760000aa (pid:130)
2014-04-15 05:16:10.329 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"ruby-1.9", :action=>"post-configure", :args=>{"--with-app-uuid"=>"534cf8d11be53ae1760000aa", "--with-app-name"=>"rb91", "--with-expose-ports"=>false, "--with-container-uuid"=>"534cf8d11be53ae1760000aa", "--with-container-name"=>"rb91", "--with-namespace"=>"test", "--with-request-id"=>"8b4660554fe28fd04bdb0c9ba41f42c1", "--component-name"=>"ruby-1.9", "--cart-name"=>"ruby-1.9", "--with-software-version"=>"1.9", "--cartridge-vendor"=>"redhat"}}, ip-10-111-157-19, {'identity' => ip-10-111-157-19}) (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:12.274 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x0000000740c868 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-111-157-19", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"Starting Ruby cartridge\n", :exitcode=>0, :addtl_params=>{:deployments=>[{:id=>"b6d2574b", :ref=>"master", :sha1=>"3a47587", :force_clean_build=>nil, :hot_deploy=>nil, :created_at=>1397553364.8179998, :activations=>[1397553371.1347947]}]}}}>] (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:12.287 [DEBUG] DEBUG: MCollective Response Time (execute_direct: post-configure): 1.704436466s  (Request ID: 8b4660554fe28fd04bdb0c9ba41f42c1) (pid:130)
2014-04-15 05:16:12.328 [DEBUG] Execute TrackUsageOp gear_id=534cf8d11be53ae1760000aa (pid:130)
2014-04-15 05:16:12.206 [DEBUG] SUCCESS ACTION=ADD_APPLICATION USER_ID=534cf79d1be53ae17600008c LOGIN=xtian+test2@redhat.com APP_UUID=534cf8d11be53ae1760000aa DOMAIN=test Application rb91 was created. (pid:130)

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