Win2016 AD auth problem

Support
#1

Hello, guys.

We have strange problem with our test ManageIQ installation. Our setup is: 4 MIQ servers working with one DB. All of them was correctly working with Windows Server 2016 AD.

But last week we met the next problem:

3 of 4 servers are not passing to login AD user with message


**Login not allowed, User's User is missing. Please contact the administrator**

In evm.log I see this:


[----] I, [2020-05-12T11:03:21.117261 #25961:4b1b990]  INFO -- : <AuditSuccess> MIQ(Base.audit_success) userid: [av.trifonov] - User av.trifonov successfully validated by External httpd

[----] I, [2020-05-12T11:03:21.124620 #25961:4b1b990]  INFO -- : MIQ(MiqTask#update_status) Task: [5786] [Active] [Ok] [Authorizing]

[----] I, [2020-05-12T11:03:21.140852 #25961:4b1b990]  INFO -- : <AuditSuccess> MIQ(Base.audit_success) userid: [av.trifonov] - User creation successful for User: av.trifonov with ID: av.trifonov

[----] I, [2020-05-12T11:03:21.154948 #25961:4b1b990]  INFO -- : MIQ(MiqQueue.put) Message id: [1530499],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 2], "user_created", {:event_details=>"User creation successful for User: av.trifonov with ID: av.trifonov"}]

[----] W, [2020-05-12T11:03:21.155269 #25961:4b1b990]  WARN -- : MIQ(Authenticator::Httpd#authorize) Authentication failed for userid av.trifonov, unable to match user's group membership to an EVM role

[----] W, [2020-05-12T11:03:21.164011 #25961:4b1b990]  WARN -- : <AuditFailure> MIQ(Base.audit_failure) userid: [av.trifonov] - Authentication failed for userid av.trifonov, unable to match user's group membership to an EVM role

[----] I, [2020-05-12T11:03:21.170597 #25961:4b1b990]  INFO -- : MIQ(MiqQueue.put) Message id: [1530500],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 2], "login_failed", {:event=>"authorize", :userid=>"av.trifonov", :message=>"Authentication failed for userid av.trifonov, unable to match user's group membership to an EVM role"}]

[----] I, [2020-05-12T11:03:21.182482 #25961:4b1b990]  INFO -- : <AuditSuccess> MIQ(Base.audit_success) userid: [av.trifonov] - Authentication successful for user av.trifonov

/usr/local/lib/ruby/gems/2.5.0/bundler/gems/manageiq-ui-classic-d44320707dfe/app/services/user_validation_service.rb:109: warning: UserValidationService#initiate_wait_for_task at /usr/local/lib/ruby/2.5.0/forwardable.rb:137 forwarding to private method DashboardController#initiate_wait_for_task

[----] I, [2020-05-12T11:03:22.494010 #25961:4b1baa8]  INFO -- : MIQ(MiqTask#check_active) Task deleted; id: [5786]

[----] E, [2020-05-12T11:03:22.498886 #25961:4b1baa8] ERROR -- : MIQ(dashboard_controller-wait_for_task): Login not allowed, User's User is missing. Please contact the administrator

[----] I, [2020-05-12T11:03:24.049620 #25668:11c25f4]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2020-05-12 08:03:24 UTC]...

[----] I, [2020-05-12T11:03:24.057900 #25668:11c25f4]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2020-05-12 08:03:24 UTC]...Complete

[----] I, [2020-05-12T11:03:24.141416 #25858:11c25f4]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.

[----] I, [2020-05-12T11:03:24.848841 #25668:11c25f4]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 3 miq_queue rows for queue_name=generic, wcount=4, priority=200

In production.log:


[----] I, [2020-05-12T11:04:49.499603 #25961:4b1bd00]  INFO -- : Started POST "/dashboard/external_authenticate" for 10.31.252.215 at 2020-05-12 11:04:49 +0300

[----] I, [2020-05-12T11:04:49.502062 #25961:4b1bd00]  INFO -- : Processing by DashboardController#external_authenticate as JS

[----] I, [2020-05-12T11:04:49.502137 #25961:4b1bd00]  INFO -- :   Parameters: {"user_name"=>"av.trifonov@**DOMAIN**", "user_password"=>"[FILTERED]", "browser_name"=>"Firefox", "browser_version"=>"76", "browser_os"=>"Windows", "user_TZO"=>"3"}

[----] I, [2020-05-12T11:04:49.559263 #25961:4b1bd00]  INFO -- : Completed 200 OK in 57ms (Views: 0.6ms | ActiveRecord: 37.4ms)

[----] I, [2020-05-12T11:04:50.843104 #25961:4b1b990]  INFO -- : Started POST "/dashboard/wait_for_task?escape=false&task_id=5787" for 10.31.252.215 at 2020-05-12 11:04:50 +0300

[----] I, [2020-05-12T11:04:50.845657 #25961:4b1b990]  INFO -- : Processing by DashboardController#wait_for_task as JS

[----] I, [2020-05-12T11:04:50.845724 #25961:4b1b990]  INFO -- :   Parameters: {"authenticity_token"=>"**TOKEN_HERE**", "escape"=>"false", "task_id"=>"5787"}

[----] I, [2020-05-12T11:04:50.861006 #25961:4b1b990]  INFO -- :   Rendered /usr/local/lib/ruby/gems/2.5.0/bundler/gems/manageiq-ui-classic-d44320707dfe/app/views/layouts/_flash_msg.html.haml (0.1ms)

[----] I, [2020-05-12T11:04:50.861562 #25961:4b1b990]  INFO -- : Completed 200 OK in 16ms (Views: 0.7ms | ActiveRecord: 7.8ms)

I’m confused - we have same auth settings on all MIQ servers.
I’ve seen this problem. But our LDAP server is on the same VMware cluster.

#2

Could you help me to find the way of troubleshooting?

#3

I’ve solved problem.

In the /var/www/miq/vmdb/log/apache/ssl_error.log I’ve found some eroors like this:


[Thu May 14 13:09:31.156402 2020] [intercept_form_submit:info] [pid 12703] [client 10.31.252.184:22121] login found in POST: user_name=av.trifonov@DOMAIN, referer: https://10.31.136.147/

[Thu May 14 13:09:31.156406 2020] [intercept_form_submit:info] [pid 12703] [client 10.31.252.184:22121] password found in POST: user_password=[REDACTED], referer: https://10.31.136.147/

[Thu May 14 13:09:31.238516 2020] [authnz_pam:info] [pid 12703] [client 10.31.252.184:22121] PAM authentication passed for user av.trifonov@DOMAIN, referer: https://10.31.136.147/

[Thu May 14 13:09:31.238768 2020] [lookup_identity:debug] [pid 12703] mod_lookup_identity.c(445): [client 10.31.252.184:22121] invoked for user av.trifonov@DOMAIN, referer: https://10.31.136.147/

[Thu May 14 13:09:31.240284 2020] [lookup_identity:error] [pid 12703] [client 10.31.252.184:22121] Error dbus calling GetUserGroups(av.trifonov@DOMAIN): org.freedesktop.DBus.Error.AccessDenied: User 48 not in ACL\n, referer: https://10.31.136.147/

[Thu May 14 13:09:31.240636 2020] [lookup_identity:error] [pid 12703] [client 10.31.252.184:22121] Error dbus calling GetUserAttr(av.trifonov@DOMAIN, sn, mail, displayname, domainname, givenname): org.freedesktop.DBus.Error.AccessDenied: User 48 not in ACL\n, referer: https://10.31.136.147/

In the /etc/sssd/sssd.conf of the problem machines was no apache in allowed_uids.

Problem solved.

2 Likes