Bug #27953
openrole / user updates fail with API when done in non-atomic fashion
Description
Using the Foreman API (1.19.1 up through 1.23) to change user passwords seem to fail when ran consecutively.
In QUADS (our scheduling framework for managing scale/perf Engineering labs) we perform this task via:
https://github.com/redhat-performance/quads/blob/master/quads/tools/foreman.py
Because we're calling asyncio the failures ultimately get recorded and re-queued until the successfully complete.
In our specific usage of the Foreman API everything else is not repeated (singleton), however there are times only with Foreman user password updates that may be run twice and these can fail.
With every set of tasks we see a certain number of failures for this specific task.
In working with Zhenech on #theforeman he can reproduce this also on a fresh 1.23 which results in a failure.
for i in $(seq 10); do curl -XPUT -k -u admin:changeme -H 'Content-Type: application/json' -d'{"user":{"role_ids":[12,13]}}' https://localhost/api/v2/users/5 & done
Updated by Will Foster about 5 years ago
- Found in Releases 1.19.1, 1.23.1 added
- Found in Releases deleted (
1.19.0, 1.23.0)
The behaviour we'd expect to see is that each user password update via the API is successful.
(more about our usage)
In our usage, we have a number of criteria that needs to be met before a bare-metal system (one among many) is considered successfully provisioned.
1) (foreman) kickstart successful / system not marked for build
2) (foreman) correct roles + filters associated with system
3) (foreman) foreman user password is updated
4) (external) system switch configuration updated
5) (external) system IPMI credentials updated
If any one of the above fails, the system in question is requeued to try again. Only when the sum of these changes are all successful does a machine "pass" provisioning. Because any one of these can fail (most often due to kickstart taking some time to finish so the system still shows as marked for build) some of these actions are re queued and run multiple times.
3 above - (foreman) foreman user password is updated results in failure if run multiple times.
Updated by Gonzalo Rafuls about 5 years ago
We have seen this occurring when trying to update the same user twice concurrently.
We are seeing the following trace on foreman logs:
2019-09-26T10:38:16 [I|app|] Started PUT "/api/v2/users/34" for 10.1.38.171 at 2019-09-26 10:38:16 +0000 2019-09-26T10:38:16 [I|app|6f2fa] Processing by Api::V2::UsersController#update as JSON 2019-09-26T10:38:16 [I|app|6f2fa] Parameters: {"user"=>{"role_ids"=>[309, ..., 505, 83]}, "apiv"=>"v2", "id"=>"34"} 2019-09-26T10:38:16 [D|app|6f2fa] Authenticated user admin against INTERNAL authentication source 2019-09-26T10:38:16 [D|app|6f2fa] Current user set to foreman_admin (admin) 2019-09-26T10:38:16 [I|app|6f2fa] Authorized user admin(Admin User) 2019-09-26T10:38:16 [I|app|6f2fa] Current user set to admin (admin) 2019-09-26T10:38:17 [I|aud|6f2fa] update event for User with id 34 2019-09-26T10:38:17 [W|app|6f2fa] Action failed RuntimeError: resource have no errors /usr/share/foreman/app/controllers/api/base_controller.rb:143:in `process_resource_error' /usr/share/foreman/app/controllers/api/v2/users_controller.rb:99:in `update' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/abstract_controller/base.rb:186:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal/rendering.rb:30:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/abstract_controller/callbacks.rb:20:in `block in process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108:in `block in run_callbacks' /usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in `disable_json_root' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.7.1/lib/audited/sweeper.rb:14:in `around' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.7.1/lib/audited/sweeper.rb:14:in `around' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117:in `block in run_callbacks' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135:in `run_callbacks' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/abstract_controller/callbacks.rb:19:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal/rescue.rb:20:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `block in instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166:in `instrument' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal/instrumentation.rb:30:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal/params_wrapper.rb:252:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activerecord-5.1.6/lib/active_record/railties/controller_runtime.rb:22:in `process_action' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/abstract_controller/base.rb:124:in `process' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionview-5.1.6/lib/action_view/rendering.rb:30:in `process' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal.rb:189:in `dispatch' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_controller/metal.rb:253:in `dispatch' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:49:in `dispatch' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:31:in `serve' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/routing/mapper.rb:16:in `block in <class:Constraints>' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/routing/mapper.rb:46:in `serve' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:50:in `block in serve' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:33:in `each' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:33:in `serve' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:844:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.9/lib/apipie/static_dispatcher.rb:65:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.9/lib/apipie/extractor/recorder.rb:136:in `call' /usr/share/foreman/lib/middleware/telemetry.rb:9:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.9/lib/apipie/middleware/checksum_in_headers.rb:27:in `call' /usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/etag.rb:25:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/conditional_get.rb:38:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/head.rb:12:in `call' /usr/share/foreman/lib/middleware/logging_context.rb:23:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:232:in `context' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:226:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/cookies.rb:613:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:97:in `run_callbacks' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/callbacks.rb:24:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/railties-5.1.6/lib/rails/rack/logger.rb:36:in `call_app' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/railties-5.1.6/lib/rails/rack/logger.rb:26:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/remote_ip.rb:79:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/request_id.rb:25:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/method_override.rb:22:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/runtime.rb:22:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/executor.rb:12:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/actionpack-5.1.6/lib/action_dispatch/middleware/static.rb:125:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/sendfile.rb:111:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-5.0.5/lib/secure_headers/middleware.rb:13:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/railties-5.1.6/lib/rails/engine.rb:522:in `call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/railties-5.1.6/lib/rails/railtie.rb:185:in `public_send' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/railties-5.1.6/lib/rails/railtie.rb:185:in `method_missing' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/urlmap.rb:68:in `block in call' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/urlmap.rb:53:in `each' /opt/theforeman/tfm-ror51/root/usr/share/gems/gems/rack-2.0.3/lib/rack/urlmap.rb:53:in `call' /usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request' /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request' /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop' /usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads' /opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context' 2019-09-26T10:38:17 [I|app|6f2fa] Rendering api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout 2019-09-26T10:38:17 [I|app|6f2fa] Rendered api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout (0.4ms) 2019-09-26T10:38:17 [I|app|6f2fa] Completed 500 Internal Server Error in 284ms (Views: 1.2ms | ActiveRecord: 115.5ms)
Updated by Will Foster about 5 years ago
- Subject changed from user password updates fail with API when done in non-atomic fashion to role / user updates fail with API when done in non-atomic fashion
Updated by Will Foster almost 5 years ago
Hey Folks, wanted to check in and see if anyone's looked at this yet or had any questions.
We recently published a blog post around using asyncio (where we discovered this) for more reference to our Foreman usage:
https://quads.dev/2019/10/04/concurrent-provisioning-with-asyncio/
Updated by Will Foster almost 5 years ago
Hey Foreman team, just checking in on this. Has anyone gotten a chance to take a look? We can reproduce this in our R&D labs if needed, right now we're limiting the potential of asyncio so we don't hit this issue but it's holding back the potential for our parallel provisioning workflow with extremely large sets of systems.