Project

General

Profile

Bug #27953

role / user updates fail with API when done in non-atomic fashion

Added by Will Foster about 2 months ago. Updated about 1 month ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
API
Target version:
-
Difficulty:
Triaged:
No
Bugzilla link:
Pull request:
Fixed in Releases:
Found in Releases:

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

History

#1 Updated by Evgeni Golov about 2 months ago

  • Category set to API

#2 Updated by Will Foster about 2 months 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.

#3 Updated by Gonzalo Rafuls about 2 months 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)

#4 Updated by Will Foster about 2 months 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

#5 Updated by Will Foster about 1 month 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/

Also available in: Atom PDF