Bug 997766

This error is expected shortly after a broker restart. Does this happen later as well?

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

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

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.

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.

Move the bug to verified according the Comment#5 and #6.

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.

Mrunal,

  It seems like PassengerSpawnIPAddress is missing at least one call to / on 127.0.0.1.

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.

Mrunal, awesome... thx for looking into this one.

-Dan

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.

Mrunal, We are already patching that same package right?

Dan, yes, we patch the passenger package today.

I agree with 2 then.

The new patched passenger rpm is now available in devenv.

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 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'

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.

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 APP_UUID=534cf8d11be53ae1760000aa DOMAIN=test Application rb91 was created. (pid:130)