Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1060760 - [new relic] MCollective::UnknownRPCError: undefined local variable or method `e' for #<MCollective::Agent::Openshift:0x00000003fbdc38>
Summary: [new relic] MCollective::UnknownRPCError: undefined local variable or method ...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: OpenShift Online
Classification: Red Hat
Component: Containers
Version: 1.x
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: ---
Assignee: Jhon Honce
QA Contact: libra bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-02-03 14:34 UTC by Jessica Forrester
Modified: 2014-03-05 03:33 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-02-26 19:10:59 UTC


Attachments (Terms of Use)

Description Jessica Forrester 2014-02-03 14:34:48 UTC
Description of problem:
AppEventsController#create, AliasController#destroy, and ApplicationsController#destroy are throwing MCollective::UnknownRPCError: undefined local variable or method `e' for #<MCollective::Agent::Openshift:0x00000003fbdc38>

Based on the stacktrace it looks like it is coming from has_app_cartridge? during a rollback.

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

stacktrace:

…/ruby193/root/usr/share/ruby/mcollective/rpc/
client.rb: 938:in `process_results_with_block'
…/ruby193/root/usr/share/ruby/mcollective/rpc/
client.rb: 855:in `block in call_agent'
…t/rh/ruby193/root/usr/share/ruby/mcollective/
client.rb: 156:in `block (2 levels) in req'
…t/rh/ruby193/root/usr/share/ruby/mcollective/
client.rb: 151:in `loop'
…t/rh/ruby193/root/usr/share/ruby/mcollective/
client.rb: 151:in `block in req'
         /opt/rh/ruby193/root/usr/share/ruby/
timeout.rb:  69:in `timeout'
…t/rh/ruby193/root/usr/share/ruby/mcollective/
client.rb: 148:in `req'
…/ruby193/root/usr/share/ruby/mcollective/rpc/
client.rb: 851:in `call_agent'
…/ruby193/root/usr/share/ruby/mcollective/rpc/
client.rb: 244:in `method_missing'
…b/openshift/
mcollective_application_container_proxy.rb:2851:in `block in has_app_cartridge?'
…b/openshift/
mcollective_application_container_proxy.rb:2340:in `rpc_exec'
…b/openshift/
mcollective_application_container_proxy.rb:2850:in `has_app_cartridge?'
…b/openshift/
mcollective_application_container_proxy.rb: 926:in `rescue in remove_component'
…b/openshift/
mcollective_application_container_proxy.rb: 923:in `remove_component'
…openshift-origin-controller-1.19.16/app/models/
gear.rb: 254:in `remove_component'
…ntroller-1.19.16/app/pending_ops_models/
add_comp_op.rb:  17:in `rollback'
…-controller-1.19.16/app/models/
pending_app_op_group.rb: 191:in `block in execute_rollback'
…-controller-1.19.16/app/models/
pending_app_op_group.rb: 184:in `each'
…-controller-1.19.16/app/models/
pending_app_op_group.rb: 184:in `execute_rollback'
….19.16/app/pending_ops_models/
add_features_op_group.rb:  21:in `execute_rollback'
…ft-origin-controller-1.19.16/app/models/
application.rb:1513:in `rescue in run_jobs'
…ft-origin-controller-1.19.16/app/models/
application.rb:1493:in `run_jobs'
…ft-origin-controller-1.19.16/app/models/
application.rb: 720:in `block in remove_features'
…ft-origin-controller-1.19.16/app/models/
application.rb:1571:in `run_in_application_lock'
…ft-origin-controller-1.19.16/app/models/
application.rb: 717:in `remove_features'
…ft-origin-controller-1.19.16/app/models/
application.rb: 751:in `destroy_app'
…ler-1.19.16/app/controllers/
applications_controller.rb: 195:in `destroy'
…troller-1.19.16/lib/openshift/controller/
action_log.rb:  80:in `set_logged_request'
…sr/share/gems/gems/journey-1.0.4/lib/journey/
router.rb:  68:in `block in call'
…sr/share/gems/gems/journey-1.0.4/lib/journey/
router.rb:  56:in `each'
…sr/share/gems/gems/journey-1.0.4/lib/journey/
router.rb:  56:in `call'
…per-0.11.1/lib/mongo_mapper/middleware/
identity_map.rb:  10:in `call'
…oid-3.0.21/lib/rack/mongoid/middleware/
identity_map.rb:  34:in `block in call'
…e/gems/gems/mongoid-3.0.21/lib/mongoid/
unit_of_work.rb:  39:in `unit_of_work'
…oid-3.0.21/lib/rack/mongoid/middleware/
identity_map.rb:  34:in `call'
…3/root/usr/share/gems/gems/rack-1.4.1/lib/rack/
etag.rb:  23:in `call'
…/share/gems/gems/rack-1.4.1/lib/rack/
conditionalget.rb:  35:in `call'
…e/gems/gems/rack-1.4.1/lib/rack/session/abstract/
id.rb: 205:in `context'
…e/gems/gems/rack-1.4.1/lib/rack/session/abstract/
id.rb: 200:in `call'
…/share/gems/gems/rack-1.4.1/lib/rack/
methodoverride.rb:  21:in `call'
…oot/usr/share/gems/gems/rack-1.4.1/lib/rack/
runtime.rb:  17:in `call'
…3/root/usr/share/gems/gems/rack-1.4.1/lib/rack/
lock.rb:  15:in `call'
…are/gems/gems/rack-cache-1.2/lib/rack/cache/
context.rb: 136:in `forward'
…are/gems/gems/rack-cache-1.2/lib/rack/cache/
context.rb: 143:in `pass'
…are/gems/gems/rack-cache-1.2/lib/rack/cache/
context.rb: 155:in `invalidate'
…are/gems/gems/rack-cache-1.2/lib/rack/cache/
context.rb:  71:in `call!'
…are/gems/gems/rack-cache-1.2/lib/rack/cache/
context.rb:  51:in `call'
…r-3.0.21/lib/phusion_passenger/rack/
request_handler.rb:  97:in `process_request'
…0.21/lib/phusion_passenger/
abstract_request_handler.rb: 521:in `accept_and_process_next_request'
…0.21/lib/phusion_passenger/
abstract_request_handler.rb: 274:in `main_loop'
…0.21/lib/phusion_passenger/rack/
application_spawner.rb: 206:in `start_request_handler'
…0.21/lib/phusion_passenger/rack/
application_spawner.rb:  79:in `block in spawn_application'
…s/gems/passenger-3.0.21/lib/phusion_passenger/
utils.rb: 470:in `safe_fork'
…0.21/lib/phusion_passenger/rack/
application_spawner.rb:  64:in `spawn_application'
…assenger-3.0.21/lib/phusion_passenger/
spawn_manager.rb: 264:in `spawn_rack_application'
…assenger-3.0.21/lib/phusion_passenger/
spawn_manager.rb: 137:in `spawn_application'
…assenger-3.0.21/lib/phusion_passenger/
spawn_manager.rb: 275:in `handle_spawn_application'
…senger-3.0.21/lib/phusion_passenger/
abstract_server.rb: 357:in `server_main_loop'
…senger-3.0.21/lib/phusion_passenger/
abstract_server.rb: 206:in `start_synchronously'

Comment 2 Andy Grimm 2014-02-03 17:56:41 UTC
There were a couple of different things happening with this gear.  It was having processes OOM killed, and also was being throttled around the same time the cartridge setup process was trying to boost the gear.  During cartridge configure, these errors occurred:

February 01 11:35:25 INFO Running install for REDACTED/mysql
February 01 11:38:54 ERROR Unexpected error during configure: Device or resource busy - /cgroup/all/openshift/REDACTED/memory.memsw.limit_in_bytes (Errno::EBUSY)
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups/libcgroup.rb:254:in `syswrite'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups/libcgroup.rb:254:in `block (2 levels) in store'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-common-1.18.9/lib/openshift-origin-common/utils/file_needs_sync.rb:38:in `block in open'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-common-1.18.9/lib/openshift-origin-common/utils/file_needs_sync.rb:36:in `open'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-common-1.18.9/lib/openshift-origin-common/utils/file_needs_sync.rb:36:in `open'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups/libcgroup.rb:253:in `block in store'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups/libcgroup.rb:249:in `each'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups/libcgroup.rb:249:in `store'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups.rb:109:in `store'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups.rb:128:in `ensure in apply_profile'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups.rb:128:in `apply_profile'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/utils/cgroups.rb:44:in `block (2 levels) in <class:Cgroups>'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:255:in `configure'
  /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/application_container_ext/cartridge_actions.rb:27:in `configure'
  /opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:883:in `block in oo_configure'
  /opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:318:in `with_container_from_args'
  /opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:882:in `oo_configure'
  /opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:144:in `execute_action'
  /opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:101:in `cartridge_do_action'
  /opt/rh/ruby193/root/usr/share/ruby/mcollective/rpc/agent.rb:86:in `handlemsg'
  /opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:126:in `block (2 levels) in dispatch'
  /opt/rh/ruby193/root/usr/share/ruby/timeout.rb:69:in `timeout'
  /opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:125:in `block in dispatch'
February 01 11:38:55 INFO Deleting private endpoints for REDACTED/mysql
February 01 11:38:55 INFO Deleted private endpoints for REDACTED/mysql
February 01 11:38:55 INFO 52c437c35973ca26740001a5 stop against 'mysql'
February 01 11:38:57 INFO Shell command '/sbin/runuser -s /bin/sh REDACTED -c "exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c1,c2' /bin/sh -c \"set -e; /var/lib/openshift/REDACTED/mysql/bin/control stop \""' ran. rc=0 out=
February 01 11:38:57 INFO Disconnecting frontend mapping for REDACTED/mysql: []
February 01 11:38:57 INFO Deleting cartridge directory for REDACTED/mysql
February 01 11:38:58 INFO Deleted cartridge directory for REDACTED/mysql
February 01 11:38:59 ERROR Cartridge directory not found for mysql-5.5
February 01 11:38:59 ERROR /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:133:in `cartridge_directory'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:143:in `get_cartridge'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/application_container.rb:606:in `get_cartridge'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:1235:in `has_app_cartridge_action'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/rpc/agent.rb:86:in `handlemsg'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:126:in `block (2 levels) in dispatch'
/opt/rh/ruby193/root/usr/share/ruby/timeout.rb:69:in `timeout'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:125:in `block in dispatch'
February 01 11:39:00 ERROR Cartridge directory not found for mysql-5.5
February 01 11:39:00 ERROR /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:133:in `cartridge_directory'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:143:in `get_cartridge'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:368:in `deconfigure'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/application_container_ext/cartridge_actions.rb:120:in `deconfigure'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:908:in `block in oo_deconfigure'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:318:in `with_container_from_args'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:907:in `oo_deconfigure'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:144:in `execute_action'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:101:in `cartridge_do_action'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/rpc/agent.rb:86:in `handlemsg'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:126:in `block (2 levels) in dispatch'
/opt/rh/ruby193/root/usr/share/ruby/timeout.rb:69:in `timeout'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:125:in `block in dispatch'
February 01 11:39:00 WARN Corrupted cartridge REDACTED/mysql-5.5 removed. There may be extraneous data left on system.
February 01 11:39:00 WARN Corrupted cartridge REDACTED/mysql-5.5. Attempting to auto-correct for deconfigure using local manifest.yml.
February 01 11:39:00 WARN Corrupted cartridge REDACTED/mysql-5.5. Attempting to auto-correct for deconfigure resorting to CartridgeRepository.
February 01 11:39:00 INFO Deleting private endpoints for REDACTED/mysql
February 01 11:39:00 INFO Deleted private endpoints for REDACTED/mysql
February 01 11:39:00 INFO REDACTED stop against 'mysql'
February 01 11:39:00 INFO /var/lib/openshift/REDACTED/mysql/metadata/managed_files.yml is missing
February 01 11:39:00 INFO Disconnecting frontend mapping for REDACTED/mysql: []
February 01 11:39:00 INFO Deleting cartridge directory for REDACTED/mysql
February 01 11:39:00 INFO Deleted cartridge directory for REDACTED/mysql
February 01 11:39:00 ERROR Cartridge directory not found for mysql-5.5
February 01 11:39:00 ERROR /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:133:in `cartridge_directory'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:143:in `get_cartridge'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/application_container.rb:606:in `get_cartridge'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:1235:in `has_app_cartridge_action'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/rpc/agent.rb:86:in `handlemsg'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:126:in `block (2 levels) in dispatch'
/opt/rh/ruby193/root/usr/share/ruby/timeout.rb:69:in `timeout'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:125:in `block in dispatch'
February 01 11:41:05 ERROR Cartridge directory not found for mysql-5.5
February 01 11:41:05 ERROR /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:133:in `cartridge_directory'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:143:in `get_cartridge'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/v2_cart_model.rb:368:in `deconfigure'
/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-node-1.19.18/lib/openshift-origin-node/model/application_container_ext/cartridge_actions.rb:120:in `deconfigure'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:908:in `block in oo_deconfigure'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:318:in `with_container_from_args'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:907:in `oo_deconfigure'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:144:in `execute_action'
/opt/rh/ruby193/root/usr/libexec/mcollective/mcollective/agent/openshift.rb:101:in `cartridge_do_action'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/rpc/agent.rb:86:in `handlemsg'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:126:in `block (2 levels) in dispatch'
/opt/rh/ruby193/root/usr/share/ruby/timeout.rb:69:in `timeout'
/opt/rh/ruby193/root/usr/share/ruby/mcollective/agents.rb:125:in `block in dispatch'
February 01 11:41:05 WARN Corrupted cartridge REDACTED/mysql-5.5 removed. There may be extraneous data left on system.
February 01 11:41:05 WARN Corrupted cartridge REDACTED/mysql-5.5. Attempting to auto-correct for deconfigure using local manifest.yml.
February 01 11:41:05 WARN Corrupted cartridge REDACTED/mysql-5.5. Attempting to auto-correct for deconfigure resorting to CartridgeRepository.
February 01 11:41:05 INFO Deleting private endpoints for REDACTED/mysql
February 01 11:41:05 INFO Deleted private endpoints for REDACTED/mysql
February 01 11:41:05 INFO REDACTED stop against 'mysql'
February 01 11:41:05 INFO /var/lib/openshift/REDACTED/mysql/metadata/managed_files.yml is missing
February 01 11:41:10 INFO Disconnecting frontend mapping for REDACTED/mysql: []
February 01 11:41:10 INFO Deleting cartridge directory for REDACTED/mysql
February 01 11:41:10 INFO Deleted cartridge directory for REDACTED/mysql

Comment 3 Abhishek Gupta 2014-02-05 21:57:58 UTC
Fixed with --> https://github.com/openshift/origin-server/pull/4672

Comment 4 openshift-github-bot 2014-02-05 23:27:18 UTC
Commit pushed to master at https://github.com/openshift/origin-server

https://github.com/openshift/origin-server/commit/1886d65be1f491b4da373532a4e81833583c9682
Fix for bug 1060760: Missing variable assignment for exception

Comment 5 Meng Bo 2014-02-12 10:23:44 UTC
Can you give some advise about how to verify this bug? It is hard to reproduce this from QE side.

Thanks.

Comment 6 Jhon Honce 2014-02-12 16:12:15 UTC
1. Create an application with the php and mysql cartridges
2. As root, rename the mysql directory in the gear to mysql_notfound
3. Attempt to remove the mysql cartridge from the gear

Comment 7 Meng Bo 2014-02-13 09:40:44 UTC
I, [2014-02-13T04:06:46.921545 #22361]  INFO -- : openshift.rb:90:in `cartridge_do_action' cartridge_do_action validation = mysql-5.5 deconfigure {"--with-app-uuid"=>"52fc8a3700536c190f000062", "--with-app-name"=>"app1", "--with-container-uuid"=>"52fc8a3700536c190f000062", "--with-container-name"=>"app1", "--with-namespace"=>"bmengdev", "--with-request-id"=>"45bc2ea37e5958504d0de0da2f540509", "--component-name"=>"mysql-5.5", "--cart-name"=>"mysql-5.5", "--with-software-version"=>"5.5", "--cartridge-vendor"=>"redhat"}
I, [2014-02-13T04:06:46.922037 #22361]  INFO -- : openshift.rb:145:in `execute_action' Executing action [deconfigure] using method oo_deconfigure with args [{"--with-app-uuid"=>"52fc8a3700536c190f000062", "--with-app-name"=>"app1", "--with-container-uuid"=>"52fc8a3700536c190f000062", "--with-container-name"=>"app1", "--with-namespace"=>"bmengdev", "--with-request-id"=>"45bc2ea37e5958504d0de0da2f540509", "--component-name"=>"mysql-5.5", "--cart-name"=>"mysql-5.5", "--with-software-version"=>"5.5", "--cartridge-vendor"=>"redhat", "--with-hourglass"=>#<OpenShift::Runtime::Utils::Hourglass:0x00000002b42100 @duration=234, @start_time=2014-02-13 04:06:46 -0500, @end_time=2014-02-13 04:10:40 -0500>}]
I, [2014-02-13T04:06:47.120223 #22361]  INFO -- : openshift.rb:159:in `execute_action' Finished executing action [deconfigure] (0) Time to execute 0.198238624
I, [2014-02-13T04:06:47.157024 #22361]  INFO -- : openshift.rb:116:in `cartridge_do_action' cartridge_do_action reply (0):
------
CLIENT_ERROR: Corrupted cartridge mysql-5.5 removed. There may be extraneous data left on system.


As step in comment#6, the above error message found in mcollective log and no such trace back issue.


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