Project

General

Profile

Actions

Bug #3882

closed

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

Added by Ward Vandewege over 9 years ago. Updated over 9 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Radhika Chippada
Category:
-
Target version:
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 2 (0 open2 closed)

Task #4104: Add test(s) to verify a cancelled job stays cancelled on further cancel actions.ResolvedRadhika Chippada10/03/2014Actions
Task #4105: Review branch: 3882-cancel-already-cancelled-jobResolvedRadhika Chippada10/03/2014Actions
Actions #1

Updated by Ward Vandewege over 9 years ago

  • Description updated (diff)
Actions #2

Updated by Tom Clegg over 9 years ago

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

Actions #3

Updated by Tom Clegg over 9 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
Actions #4

Updated by Tom Clegg over 9 years ago

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

Updated by Brett Smith over 9 years ago

  • Assigned To set to Brett Smith
Actions #6

Updated by Brett Smith over 9 years ago

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

Actions #7

Updated by Radhika Chippada over 9 years ago

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

Updated by Tom Clegg over 9 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.)

Actions #9

Updated by Radhika Chippada over 9 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.

Actions #10

Updated by Tom Clegg over 9 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.)

Actions #11

Updated by Radhika Chippada over 9 years ago

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

Applied in changeset arvados|commit:02671029e4240abb83883cb908c183c57598799e.

Actions

Also available in: Atom PDF