Bug #3882

[Workbench] fiddlesticks trying to cancel job that is already cancelled

Added by Ward Vandewege almost 5 years ago. Updated almost 5 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Radhika Chippada
Category:
-
Target version:
Start date:
10/03/2014
Due date:
% Done:

100%

Estimated time:
(Total: 1.00 h)
Story points:
0.5

Description

This job misbehaved and is spooling tons of stdout/stderr (very slowly) to crunch-dispatch. In trying to cancel it from workbench, I get this:

Started POST "/arvados/v1/jobs/qr1hi-8i9sb-u83wq14nvqfdzl3/cancel" for 127.0.0.1 at 2014-09-16 18:29:13 +0000
Processing by Arvados::V1::JobsController#cancel as */*
Parameters: {"api_token"=>"3u06bentxltg6mf243ocoygjr41dwhlqfebm87z318sn14qfw8", "reader_tokens"=>"[]", "id"=>"qr1hi-8i9sb-u83wq14nvqfdzl3"}
WARNING: Can't verify CSRF token authenticity
User qr1hi-tpzed-327pde5hktairf9 tried to change protected job attributes on locked Job qr1hi-8i9sb-u83wq14nvqfdzl3
#<ArvadosModel::PermissionDeniedError: ArvadosModel::PermissionDeniedError>
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/app/models/arvados_model.rb:292:in `ensure_permission_to_save'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:407:in `_run__962032218432037325__save__2121267314411875141__callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `__run_callback'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:385:in `_run_save_callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:81:in `run_callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/callbacks.rb:264:in `create_or_update'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/persistence.rb:104:in `save!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/validations.rb:56:in `save!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/attribute_methods/dirty.rb:33:in `save!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:264:in `block in save!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:313:in `block in with_transaction_returning_status'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:208:in `transaction'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:311:in `with_transaction_returning_status'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:264:in `save!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/persistence.rb:228:in `block in update_attributes!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:313:in `block in with_transaction_returning_status'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:208:in `transaction'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/transactions.rb:311:in `with_transaction_returning_status'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/persistence.rb:226:in `update_attributes!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/app/controllers/arvados/v1/jobs_controller.rb:99:in `cancel'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/base.rb:167:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/rendering.rb:10:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/callbacks.rb:18:in `block in process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:568:in `_run__2150664515110973502__process_action__2326252081454850858__callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `__run_callback'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:81:in `run_callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/callbacks.rb:17:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/rescue.rb:29:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/notifications.rb:123:in `block in instrument'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/notifications.rb:123:in `instrument'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/base.rb:121:in `process'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/abstract_controller/rendering.rb:45:in `process'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal.rb:203:in `dispatch'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_controller/metal.rb:246:in `block in action'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:73:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:36:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/routing/route_set.rb:608:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:177:in `call!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:157:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/omniauth-1.1.1/lib/omniauth/builder.rb:48:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/etag.rb:23:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/conditionalget.rb:35:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/head.rb:14:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/flash.rb:242:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/session/abstract/id.rb:210:in `context'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/session/abstract/id.rb:205:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/cookies.rb:341:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/query_cache.rb:64:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activerecord-3.2.17/lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `_run__864489280260259175__call__2121267314411875141__callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:405:in `__run_callback'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/callbacks.rb:81:in `run_callbacks'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/rack/logger.rb:32:in `call_app'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/rack/logger.rb:16:in `block in call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/tagged_logging.rb:22:in `tagged'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/rack/logger.rb:16:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/request_id.rb:22:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/methodoverride.rb:21:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/runtime.rb:17:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/activesupport-3.2.17/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-1.4.5/lib/rack/lock.rb:15:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/app/middlewares/arvados_api_token.rb:59:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/actionpack-3.2.17/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/engine.rb:484:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/application.rb:231:in `call'
/data/www/qr1hi.arvadosapi.com/releases/20140912201856/vendor/bundle/ruby/2.1.0/gems/railties-3.2.17/lib/rails/railtie/configurable.rb:30:in `method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:448:in `block (3 levels) in start_threads'

Error 1410892153+a317a5a1: 403


Subtasks

Task #4104: Add test(s) to verify a cancelled job stays cancelled on further cancel actions.ResolvedRadhika Chippada

Task #4105: Review branch: 3882-cancel-already-cancelled-jobResolvedRadhika Chippada

Associated revisions

Revision 02671029
Added by Radhika Chippada almost 5 years ago

closes #3882
Merge branch '3882-cancel-already-cancelled-job'

History

#1 Updated by Ward Vandewege almost 5 years ago

  • Description updated (diff)

#2 Updated by Tom Clegg almost 5 years ago

If the problem is that the job in question was already cancelled, the "cancel" action should probably respond 200 OK.

#3 Updated by Tom Clegg almost 5 years ago

  • Subject changed from [Workbench] fiddlesticks trying to cancel job to [Workbench] fiddlesticks trying to cancel job that is already cancelled
  • Story points set to 0.5

#4 Updated by Tom Clegg almost 5 years ago

  • Target version changed from Bug Triage to 2014-10-08 sprint

#5 Updated by Brett Smith almost 5 years ago

  • Assigned To set to Brett Smith

#6 Updated by Brett Smith almost 5 years ago

Tom thinks this might actually be an API-side bug. Keep that in mind.

#7 Updated by Radhika Chippada almost 5 years ago

  • Status changed from New to In Progress
  • Assigned To changed from Brett Smith to Radhika Chippada

#8 Updated by Tom Clegg almost 5 years ago

3882-cancel-already-cancelled-job at eda7aa4:

Wow, nice catch @ test_helper.rb.

In services/api/test/functional/arvados/v1/jobs_controller_test.rb the new test is good at ensuring the cancelled_at and state fields have the right content after the update attempt, but in order to confirm the reported bug is fixed I think we need to check two more things:
  • assert_response :success when already cancelled
  • Correct behavior when the "cancel" action is used

I've pushed 3882-cancel-already-cancelled-job-TC @ 8018af9 -- but the tests now fail, because the calls I expected to return 422 are returning 200 and I don't immediately see why. Do you?

(Also updated to use json_response method, and verify database row still says Cancelled.)

#9 Updated by Radhika Chippada almost 5 years ago

Tom, I changed "update_timestamps_when_state_changes" from before_validation to after_validation. Without this, the update to the object's success and running flags is resulting in overriding the actual state update. This is resulting in loss of data.
Please review. With this change, the update to success and running flags is taking place after validating the state of the object. Thanks.

#10 Updated by Tom Clegg almost 5 years ago

LGTM, thanks.

(I think it would be better form to do this in a before_save rather than after_validation -- the difference being that after_validation runs even if validation fails -- but I can't quite think of a situation where that difference would have an observable effect, given that the application itself just processes transactions.)

#11 Updated by Radhika Chippada almost 5 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 50 to 100

Applied in changeset arvados|commit:02671029e4240abb83883cb908c183c57598799e.

Also available in: Atom PDF