Could not refresh external usergroups: ActiveRecord::RecordNotFound

Problem:
Me as a User of a Group cant get the correct rights on Foreman anymore.
Other Users in the same AD Group can still login, and get the correct rights.

Expected outcome:
Login and directly get the correct Administration rights.

Foreman and Proxy versions:

foreman-proxy-2.5.2-1.el7.noarch
foreman-2.5.2-1.el7.noarch
katello-4.1.2.1-1.el7.noarch

Foreman and Proxy plugin versions:

Distribution and version:
CentOS Linux release 7.9.2009 (Core)

Other relevant data:

the production.log gives me the following logs, when i try to login

2021-09-15T14:44:44 [I|app|ced5ed36] Started POST "/users/login" for 10.2.40.1 at 2021-09-15 14:44:44 +0200
2021-09-15T14:44:44 [I|app|ced5ed36] Processing by UsersController#login as HTML
2021-09-15T14:44:44 [I|app|ced5ed36]   Parameters: {"login"=>{"login"=>"MyUser", "password"=>"[FILTERED]"}, "authenticity_token"=>"authtoken=="}
2021-09-15T14:44:45 [I|aud|ced5ed36] User (13) update event on usergroup_ids 1, 
2021-09-15T14:44:45 [I|app|ced5ed36] User 'MyUser' logged in from '10.2.40.1'
2021-09-15T14:44:45 [I|app|ced5ed36] Redirected to https://kattello.sercer.com/
2021-09-15T14:44:45 [I|app|ced5ed36] Completed 302 Found in 605ms (ActiveRecord: 128.2ms | Allocations: 154034)
2021-09-15T14:44:45 [I|app|257a89c8] Started GET "/" for 10.2.40.1 at 2021-09-15 14:44:45 +0200
2021-09-15T14:44:45 [I|app|257a89c8] Processing by DashboardController#index as HTML
2021-09-15T14:44:45 [I|app|257a89c8]   Rendering common/403.html.erb within layouts/application
2021-09-15T14:44:45 [I|app|257a89c8]   Rendered common/403.html.erb within layouts/application (Duration: 1.6ms | Allocations: 546)
2021-09-15T14:44:45 [I|app|257a89c8]   Rendered layouts/_application_content.html.erb (Duration: 0.9ms | Allocations: 507)
2021-09-15T14:44:45 [I|app|257a89c8]   Rendering layouts/base.html.erb
2021-09-15T14:44:45 [I|app|257a89c8]   Rendered layouts/base.html.erb (Duration: 33.2ms | Allocations: 30435)
2021-09-15T14:44:45 [I|app|257a89c8] Filter chain halted as :authorize rendered or redirected
2021-09-15T14:44:45 [I|app|257a89c8] Completed 403 Forbidden in 95ms (Views: 46.0ms | ActiveRecord: 4.5ms | Allocations: 57906)
2021-09-15T14:44:45 [I|app|34ec1c06] Started GET "/notification_recipients" for 10.2.40.1 at 2021-09-15 14:44:45 +0200
2021-09-15T14:44:45 [I|app|34ec1c06] Processing by NotificationRecipientsController#index as JSON
2021-09-15T14:44:46 [I|app|34ec1c06] Completed 200 OK in 79ms (Views: 0.2ms | ActiveRecord: 18.6ms | Allocations: 35670)
2021-09-15T14:44:55 [I|app|7f045391] Started GET "/notification_recipients" for 10.2.40.1 at 2021-09-15 14:44:55 +0200
2021-09-15T14:44:55 [I|app|7f045391] Processing by NotificationRecipientsController#index as JSON
2021-09-15T14:44:56 [I|app|7f045391] Completed 200 OK in 34ms (Views: 0.1ms | ActiveRecord: 2.2ms | Allocations: 18731)

When a colleague with Admin rights tries to update the User/Usergroup we get the following error displayed:

Could not refresh external usergroups: ActiveRecord::RecordNotFound - Couldn't find all Users with 'id': (10, 14, 7, 16, 6, 12, 5, 13) [WHERE (users.id IN (5,6,7,8,9,10,14,15,16,17,18,7,10,16,12,14,6,5,18,2,4,1,3,5))] (found 7 results, but was looking for 8). Couldn't find User with id 13. -

Do you guys got any Idea or Tips where to look or even better to fix this error?
If you need any other logs or information please let me know!

Thank you!

Thanks for posting about this. Let’s see if we can see what’s going on here and help you out.

1 Like

Can someone from the Foreman team give this a look? @ekohl et al?

This is not an area I’m familiar with.

Who would you suggest as a good person to ask about it?

Check the user 13, does it have correct auth source assigned? Is the user assigned to the same organization amd location as that LDAP auth source? Usually when something can’t be found but exists, it’s due to the taxonomies (orgs and locs)

Hi Marek!

First Thanks for the Help!
I have compared two users (me where it does not work) and a colleague (where it works). We are in the same organization,location and have the same attribute.

Ok, let’s try some debugging. Start the rails console and try the following

foreman-rake console
u = User.find(13)
u.valid?
u.auth_source
exit

Then also try to increase the log level to debug and upload the whole request log from production.log when Admin tries to update the User/Usergroup. Hopefully that will reveal something.

Hi Marek,

here is the production.log output when we try to update the Usergroup

2021-09-16T10:07:00 [I|app|151ae3ae] Started PUT "/external_usergroups/katello-admins/refresh" for 10.40.3.18 at 2021-09-16 10:07:00 +0200
2021-09-16T10:07:00 [I|app|151ae3ae] Processing by ExternalUsergroupsController#refresh as HTML
2021-09-16T10:07:00 [I|app|151ae3ae]   Parameters: {"authenticity_token"=>"AuthToken", "id"=>"katello-admins"}
2021-09-16T10:07:00 [D|app|151ae3ae] Setting default_location_puppet_content has no definition, clean up your database
2021-09-16T10:07:00 [D|app|151ae3ae] Setting max_trend has no definition, clean up your database
2021-09-16T10:07:00 [D|tax|151ae3ae] Current location set to Duesseldorf
2021-09-16T10:07:00 [D|tax|151ae3ae] Current organization set to Organisation
2021-09-16T10:07:00 [E|app|151ae3ae] Failed to save: Could not refresh external usergroups: ActiveRecord::RecordNotFound - Couldn't find all Users with 'id': (10, 14, 7, 16, 6, 12, 5, 13) [WHERE (users.id IN (5,6,7,8,9,10,14,15,16,17,18,10,16,12,14,6,5,7,18,2,4,1,3,18))] (found 7 results, but was looking for 8). Couldn't find User with id 13. - 
2021-09-16T10:07:00 [I|app|151ae3ae] Redirected to https://foreman_server.foo.bar/usergroups/1-katello-admins/edit
2021-09-16T10:07:00 [I|app|151ae3ae] Completed 302 Found in 180ms (ActiveRecord: 6.0ms | Allocations: 36536)
2021-09-16T10:07:00 [I|app|5af73693] Started GET "/usergroups/1-katello-admins/edit" for 10.40.3.18 at 2021-09-16 10:07:00 +0200
2021-09-16T10:07:00 [I|app|5af73693] Processing by UsergroupsController#edit as HTML
2021-09-16T10:07:00 [I|app|5af73693]   Parameters: {"id"=>"1-katello-admins"}
2021-09-16T10:07:00 [D|app|5af73693] Setting default_location_puppet_content has no definition, clean up your database
2021-09-16T10:07:00 [D|app|5af73693] Setting max_trend has no definition, clean up your database
2021-09-16T10:07:00 [D|tax|5af73693] Current location set to Duesseldorf
2021-09-16T10:07:00 [D|tax|5af73693] Current organization set to Organisation
2021-09-16T10:07:00 [I|app|5af73693]   Rendering usergroups/edit.html.erb within layouts/application
2021-09-16T10:07:00 [I|app|5af73693]   Rendered usergroups/_external.html.erb (Duration: 5.2ms | Allocations: 7249)
2021-09-16T10:07:00 [I|app|5af73693]   Rendered usergroups/_external.html.erb (Duration: 4.8ms | Allocations: 7243)
2021-09-16T10:07:00 [I|app|5af73693]   Rendered usergroups/_form.html.erb (Duration: 41.7ms | Allocations: 34030)
2021-09-16T10:07:00 [I|app|5af73693]   Rendered usergroups/edit.html.erb within layouts/application (Duration: 46.8ms | Allocations: 40341)
2021-09-16T10:07:00 [I|app|5af73693]   Rendered layouts/_application_content.html.erb (Duration: 3.6ms | Allocations: 6651)
2021-09-16T10:07:00 [I|app|5af73693]   Rendering layouts/base.html.erb
2021-09-16T10:07:00 [I|app|5af73693]   Rendered layouts/base.html.erb (Duration: 22.1ms | Allocations: 26071)
2021-09-16T10:07:00 [I|app|5af73693] Completed 200 OK in 113ms (Views: 71.9ms | ActiveRecord: 6.2ms | Allocations: 98190)
2021-09-16T10:07:00 [D|dyn|]          Step 351346ac-0f64-4828-b507-8b07d1577e51: 2 got event Dynflow::Action::WithPollingSubPlans::Poll
2021-09-16T10:07:00 [D|dyn|]          Step 351346ac-0f64-4828-b507-8b07d1577e51: 2 suspended >>   running in phase      Run Actions::RemoteExecution::RunHostsJob
2021-09-16T10:07:00 [D|tax|] Current organization set to Organisation
2021-09-16T10:07:00 [D|tax|] Current location set to Duesseldorf
2021-09-16T10:07:00 [D|app|e6f65808] Setting default_location_puppet_content has no definition, clean up your database
2021-09-16T10:07:00 [D|app|e6f65808] Setting max_trend has no definition, clean up your database
2021-09-16T10:07:00 [D|tax|e6f65808] Current organization set to none
2021-09-16T10:07:00 [D|tax|e6f65808] Current location set to none
2021-09-16T10:07:00 [D|dyn|e6f65808]          Step 351346ac-0f64-4828-b507-8b07d1577e51: 2   running >> suspended in phase      Run Actions::RemoteExecution::RunHostsJob
2021-09-16T10:07:01 [I|app|df39bb50] Started GET "/notification_recipients" for 10.40.3.18 at 2021-09-16 10:07:01 +0200
2021-09-16T10:07:01 [I|app|df39bb50] Processing by NotificationRecipientsController#index as JSON
2021-09-16T10:07:01 [D|app|df39bb50] Setting default_location_puppet_content has no definition, clean up your database
2021-09-16T10:07:01 [D|app|df39bb50] Setting max_trend has no definition, clean up your database
2021-09-16T10:07:01 [D|tax|df39bb50] Current location set to Duesseldorf
2021-09-16T10:07:01 [D|tax|df39bb50] Current organization set to Organisation
2021-09-16T10:07:01 [D|not|df39bb50] Cache Hit: notification, reading cache for notification-18
2021-09-16T10:07:01 [D|app|df39bb50] Body: {"notifications":[{"id":253261,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.412Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253241,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.367Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253234,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.377Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253224,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.383Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253203,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.362Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253202,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.385Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253196,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.387Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253191,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.358Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253185,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.370Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253183,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.360Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253182,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.353Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253181,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.365Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253178,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.351Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253167,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.356Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253161,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.346Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}},{"id":253134,"seen":false,"level":"warning","text":"There are 240 paused tasks in the system that need attention","created_at":"2021-09-16T08:03:48.309Z","group":"Tasks","actions":{"links":[{"href":"/foreman_tasks/tasks?search=state%3Dpaused","title":"List of tasks"}]}}]}
2021-09-16T10:07:01 [I|app|df39bb50] Completed 200 OK in 37ms (Views: 0.1ms | ActiveRecord: 1.3ms | Allocations: 17666)
2021-09-16T10:07:01 [I|app|af1d5014] Started GET "/rhsm/" for 10.16.15.86 at 2021-09-16 10:07:01 +0200
2021-09-16T10:07:01 [I|app|af1d5014] Processing by Katello::Api::V2::RootController#rhsm_resource_list as JSON
2021-09-16T10:07:01 [I|app|af1d5014]   Parameters: {"root"=>{}}
2021-09-16T10:07:01 [D|app|af1d5014] Setting default_location_puppet_content has no definition, clean up your database
2021-09-16T10:07:01 [D|app|af1d5014] Setting max_trend has no definition, clean up your database
2021-09-16T10:07:01 [I|app|af1d5014]   Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.2.1/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection
2021-09-16T10:07:01 [I|app|af1d5014]   Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.2.1/app/views/katello/api/v2/root/resource_list.json.rabl within katello/api/v2/layouts/collection (Duration: 3.0ms | Allocations: 3746)
2021-09-16T10:07:01 [I|app|af1d5014] Completed 200 OK in 46ms (Views: 5.2ms | ActiveRecord: 3.0ms | Allocations: 30108)
2021-09-16T10:07:01 [D|app|af1d5014] With body: [{"href":"/rhsm/consumers","rel":"consumers"},{"href":"/rhsm/hypervisors","rel":"hypervisors"},{"href":"/rhsm/hypervisors/:owner","rel":":owner"},{"href":"/rhsm/hypervisors/:owner/heartbeat","rel":"heartbeat"},{"href":"/rhsm/owners/:organization_id/environments","rel":"environments"},{"href":"/rhsm/owners/:organization_id/pools","rel":"pools"},{"href":"/rhsm/owners/:organization_id/servicelevels","rel":"servicelevels"},{"href":"/rhsm/owners/:organization_id/system_purpose","rel":"system_purpose"},{"href":"/rhsm/environments/:environment_id/consumers","rel":"consumers"},{"href":"/rhsm/users/:login/owners","rel":"owners"},{"href":"/rhsm/consumers/:id/accessible_content","rel":"accessible_content"},{"href":"/rhsm/consumers/:id/certificates","rel":"certificates"},{"href":"/rhsm/consumers/:id/release","rel":"release"},{"href":"/rhsm/consumers/:id/compliance","rel":"compliance"},{"href":"/rhsm/consumers/:id/purpose_compliance","rel":"purpose_compliance"},{"href":"/rhsm/consumers/:id/certificates/serials","rel":"serials"},{"href":"/rhsm/consumers/:id/entitlements","rel":"entitlements"},{"href":"/rhsm/consumers/:id/entitlements/pool/:poolId","rel":":poolId"},{"href":"/rhsm/consumers/:id/entitlements/dry-run","rel":"dry-run"},{"href":"/rhsm/consumers/:id/owner","rel":"owner"},{"href":"/rhsm/consumers/:consumer_id/certificates","rel":"certificates"},{"href":"/rhsm/consumers/:id/deletionrecord","rel":"deletionrecord"},{"href":"/rhsm/pools","rel":"pools"},{"href":"/rhsm/deleted_consumers","rel":"deleted_consumers"},{"href":"/rhsm/entitlements","rel":"entitlements"},{"href":"/rhsm/subscriptions","rel":"subscriptions"},{"href":"/rhsm/consumers/:id/profiles","rel":"profiles"},{"href":"/rhsm/consumers/:id/profile","rel":"profile"},{"href":"/rhsm/consumers/:id/packages","rel":"packages"},{"href":"/rhsm/systems/:id/deb_package_profile","rel":"deb_package_profile"},{"href":"/rhsm/consumers/:id/tracer","rel":"tracer"},{"href":"/rhsm/consumers/:id/checkin","rel":"checkin"},{"href":"/rhsm/consumers/:id/guestids","rel":"guestids"},{"href":"/rhsm/consumers/:id/content_overrides","rel":"content_overrides"},{"href":"/rhsm/consumers/:id/available_releases","rel":"available_releases"},{"href":"/rhsm/systems/:id/enabled_repos","rel":"enabled_repos"},{"href":"/rhsm/jobs/:jobId","rel":":jobId"},{"href":"/rhsm/status","rel":"status"}]
 af1d5014 | 
 af1d5014 | 

And this is the output of your command:

 foreman-rake console
`/usr/share/foreman` is not writable.
Bundler will use `/tmp/bundler20210916-236676-ukok1z236676' as your home directory temporarily.
Rubocop not loaded.
API controllers newer than Apipie cache! Run apipie:cache rake task to regenerate cache.
Loading production environment (Rails 6.0.3.7)
irb(main):001:0> u = User.find(13)
=> #<User id: 13, login: "u090459", firstname: "Dennis", lastname: "KREGGENWINKEL", mail: "dennis.kr...
irb(main):002:0> u.valid?
=> true
irb(main):003:0> u.auth_source
=> #<AuthSourceLdap id: 3, type: "AuthSourceLdap", name: "ldap.foo.bar", host: "ldap.foo.bar", port: 636, account: "", account_password: [FILTERED], base_dn: "dc=retail-sc,dc=com", attr_login: "uid", attr_firstname: "givenName", attr_lastname: "sn", attr_mail: "mail", onthefly_register: true, tls: true, created_at: "2019-01-10 13:25:23", updated_at: "2019-01-10 13:25:23", ldap_filter: "(&(!(expireddate=*))(service=katello)(objectclass=...", attr_photo: "jpegPhoto", server_type: "posix", groups_base: "ou=groups,dc=foo,dc=bar", usergroup_sync: true, use_netgroups: false>
irb(main):004:0> exit

Hey @Kreggenwinkel - did you get anywhere with this?

Weird, all looks correct there. If I give you a patch to log what ecxactly prevemts the save, will you be able to apply it, restart Foreman amd check the log again? I know it’s not possible in some environments.

Hi Marek,
sorry for the delay.
Sure we can Test the Patch and Test some things if you can provide it :slight_smile: