Bug #3882
closed
[Workbench] fiddlesticks trying to cancel job that is already cancelled
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
Updated by
Updated by Tom Clegg about 10 years ago
If the problem is that the job in question was already cancelled, the "cancel" action should probably respond 200 OK.
Updated by Tom Clegg about 10 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
Updated by Tom Clegg about 10 years ago
- Target version changed from Bug Triage to 2014-10-08 sprint
Updated by Brett Smith about 10 years ago
Tom thinks this might actually be an API-side bug. Keep that in mind.
Updated by Radhika Chippada about 10 years ago
- Status changed from New to In Progress
- Assigned To changed from Brett Smith to Radhika Chippada
Updated by Tom Clegg about 10 years ago
3882-cancel-already-cancelled-job at eda7aa4:
Wow, nice catch @ test_helper.rb.
Inservices/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 :successwhen 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.)
Updated by Radhika Chippada about 10 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.
Updated by Tom Clegg about 10 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.)
Updated by Radhika Chippada about 10 years ago
- Status changed from In Progress to Resolved
- % Done changed from 50 to 100
Applied in changeset arvados|commit:02671029e4240abb83883cb908c183c57598799e.