Win2016 AD auth problem

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.

Could you help me to find the way of troubleshooting?

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