Bug 973795 - cannot delete an app with malformed database entry
cannot delete an app with malformed database entry
Status: CLOSED CURRENTRELEASE
Product: OpenShift Online
Classification: Red Hat
Component: Pod (Show other bugs)
2.x
Unspecified Unspecified
unspecified Severity low
: ---
: ---
Assigned To: Abhishek Gupta
libra bugs
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-06-12 14:40 EDT by Andy Grimm
Modified: 2016-11-07 22:47 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-07-22 11:16:17 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 Andy Grimm 2013-06-12 14:40:29 EDT
I am trying to administratively delete an app which has bad data in mongo, and even "force-destroy" is giving errors.

I originally thought this was the same as https://bugzilla.redhat.com/show_bug.cgi?id=972958 , but the database problem is different.

As mentioned there, the problem in the database is this:

"group_instances" : [
	{
		"_id" : ObjectId("51b552d4e0b8cd8dde000051"),
		"gears" : [
			{
			"_id" : ObjectId("51b552d4e0b8cd8dde00003d"),
			"app_dns" : true,
			"host_singletons" : true,
			"name" : "tv",
			"quarantined" : false,
			"server_identity" : "ex-std-node134.prod.rhcloud.com",
			"uid" : 1899,
			"uuid" : "51b552d4e0b8cd8dde00003d"
			}
		]
	},
	{
		"gears" : {
			"0" : {
			"server_identity" : "ex-std-node93.prod.rhcloud.com",
			"uid" : 3282
			}
		}
	}
],

the second "gears" is a partial entry and of the wrong data type (a dictionary instead of an array).  The user says the problem occurred when they tried to add the mongodb cartridge to their app, and broker logs seem to agree with that.  I'll try to get relevant entries from the log, but at this point, the user just wants the app deleted.
Comment 1 Andy Grimm 2013-06-12 15:45:13 EDT
I would like to work around this by simply putting a begin / rescue in a copy of the oo-admin-ctl-app code to skip deleting the malformed gear.  I've checked for the existence of the UID on the specified node, and it's not there. 

so, the code will look something like this:

      app.group_instances.each { |gi|.
        begin
          gi.gears.each { |g|.
            g.deregister_dns rescue nil
            puts "deleting #{g.name}"
            g.destroy_gear rescue nil
          } if gi.gears
        rescue
            puts "malformed gears"
        end
      } if app.group_instances
      app.delete

Is this okay?
Comment 2 Andy Grimm 2013-06-13 10:28:08 EDT
This is the first error I've correlated in the logs, but this looks like a symptom, not the cause.  I'm continuing to look for clues.

2013-06-10 00:46:12.945 [ERROR] Failed to get gear groups due to: undefined method `get_show_state_job' for nil:NilClass ["/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/gear.rb:208:in `block in get_gear_states'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/remote_job.rb:54:in `call'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/remote_job.rb:54:in `block in run_parallel_on_gears'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/remote_job.rb:53:in `each'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/remote_job.rb:53:in `run_parallel_on_gears'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/gear.rb:207:in `get_gear_states'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/models/application.rb:658:in `get_gear_states'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/app/controllers/gear_groups_controller.rb:10:in `index'",
 "/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:492:in `block in _run__759284514092967086__process_action__1011990713877997187__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_371'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.9.13/lib/openshift/controller/action_log.rb:34:in `set_logged_request'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_371'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:403:in `_run__759284514092967086__process_action__1011990713877997187__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/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/mongo_mapper-0.11.1/lib/mongo_mapper/middleware/identity_map.rb:10:in `call'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/mongoid-3.0.21/lib/rack/mongoid/middleware/identity_map.rb:34:in `block in call'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/mongoid-3.0.21/lib/mongoid/unit_of_work.rb:39:in `unit_of_work'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/mongoid-3.0.21/lib/rack/mongoid/middleware/identity_map.rb:34: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:25: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__1602819819118115128__call__1008311328904798178__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/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-1.4.1/lib/rack/lock.rb:15: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:245:in `fetch'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'",
 "/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:66: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/passenger-spawn-server:102:in `<main>'"] (pid:9197)
Comment 3 Andy Grimm 2013-06-13 10:48:53 EDT
It appears that the call to add an embedded mongodb-2.2 cartridge returned "Completed 422 Unprocessable Entity".

2013-06-10 00:45:00.345 [INFO ] Started POST "/broker/rest/domains/pyapi/applications/tv/cartridges.json" for 127.0.0.1 at 2013-06-10 00:45:00 -0400 (pid:27818)
2013-06-10 00:45:00.350 [INFO ] Parameters: {"name"=>"mongodb-2.2", "url"=>nil, "domain_id"=>"pyapi", "application_id"=>"tv", "emb_cart"=>{"name"=>"mongodb-2.2", "url"=>nil}} (pid:27818)
2013-06-10 00:45:00.350 [INFO ] Processing by EmbCartController#create as JSON (pid:27818)
2013-06-10 00:45:00.365 [DEBUG] MOPED: 10.77.7.15:27017 QUERY        database=openshift_broker collection=authorizations selector={"$query"=>{"token"=>"*****"}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil (6.1777ms) (pid:27818)
2013-06-10 00:45:00.368 [DEBUG] MOPED: 10.77.7.15:27017 QUERY        database=openshift_broker collection=cloud_users selector={"$query"=>{"_id"=>"*****1be"}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil (1.8561ms) (pid:27818)
2013-06-10 00:45:00.372 [DEBUG] MOPED: 10.77.7.15:27017 QUERY        database=openshift_broker collection=domains selector={"$query"=>{"owner_id"=>"*****1be", "canonical_namespace"=>"pyapi"}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil (1.8356ms) (pid:27818)
2013-06-10 00:45:00.376 [DEBUG] MOPED: 10.77.7.15:27017 QUERY        database=openshift_broker collection=applications selector={"$query"=>{"domain_id"=>"*****053", "canonical_name"=>"tv"}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil (3.2995ms) (pid:27818)
2013-06-10 00:45:00.387 [INFO ] Completed 422 Unprocessable Entity in 37ms (Views: 6.9ms) (pid:27818)

The 422 status code seems to happen relatively frequently in our logs, but this is the last POST operation before the "Failed to get gear groups" messages start occurring (at 00:45:05)
Comment 4 manoj 2013-06-18 16:06:46 EDT
Lowering severity as this is not a release blocker. Abhishek will add comments based on his findings
Comment 5 Abhishek Gupta 2013-07-10 19:57:50 EDT
These cases were happening because the script to clear the pending ops were working on stale data. That has been fixed and this should not be a problem any more.
Comment 6 Jianwei Hou 2013-07-11 01:35:25 EDT
The malformed database entries has not been reproduced recently, it is most possible such entries got created when something happened unexpectedly and the broker failed to rollback the some actions, leaving the application in a broken state.
I have been able to rollback application creation and deletions, according to comment 5, now that this is fixed on prod, I'm moving this bug to verified.

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