Re: [ovirt-users] Hosted engine Single Sign-On to VM with freeIPA not working

Hi, I am having an issue with getting SSO to work when a standard user(UserRole) logs in to the UserPortal. The user has permission to use only this VM, so after login the console is automatically opened for that VM. Problem is that it doesn't login on the VM system with the provided credentials. Manual login at the console works without any issues. HBAC-rule check on IPA shows access is granted. Client has SELINUX in permissive mode and a disabled firewalld. On the client side I do see some PAM related errors in the logs (see details below). Extensive Google search on error 17 "Failure setting user credentials" didn't show helpful information :-( AFAIK this is did a pretty standard set-up, all working with RH-family products. I would expect others to encounter this issue as well. If someone knows any solution or has some directions to fix this it would be greatly appreciated. Thanks, Paul ------------------------------------------------------ System setup: I have 3 systems The connection between the Engine and IPA is working fine. (I can log in with IPA users etc.) Connection is made according to this document: https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Virtuali... Configuration of the client is done according to this document: https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Virtuali... --- Hosted Engine: [root@engine ~]# cat /etc/redhat-release CentOS Linux release 7.2.1511 (Core) [root@engine ~]# uname -a Linux engine.DOMAIN.COM 3.10.0-327.10.1.el7.x86_64 #1 SMP Tue Feb 16 17:03:50 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [root@engine ~]# rpm -qa | grep ovirt ovirt-vmconsole-1.0.0-1.el7.centos.noarch ovirt-engine-restapi-3.6.2.6-1.el7.centos.noarch ovirt-setup-lib-1.0.1-1.el7.centos.noarch ovirt-engine-setup-plugin-ovirt-engine-common-3.6.3.4-1.el7.centos.noarch ovirt-engine-setup-3.6.3.4-1.el7.centos.noarch ovirt-image-uploader-3.6.0-1.el7.centos.noarch ovirt-engine-extension-aaa-jdbc-1.0.5-1.el7.noarch ovirt-host-deploy-1.4.1-1.el7.centos.noarch ovirt-engine-extension-aaa-ldap-setup-1.1.2-1.el7.centos.noarch ovirt-engine-wildfly-overlay-8.0.4-1.el7.noarch ovirt-engine-wildfly-8.2.1-1.el7.x86_64 ovirt-vmconsole-proxy-1.0.0-1.el7.centos.noarch ovirt-engine-tools-3.6.2.6-1.el7.centos.noarch ovirt-engine-dbscripts-3.6.2.6-1.el7.centos.noarch ovirt-engine-backend-3.6.2.6-1.el7.centos.noarch ovirt-engine-3.6.2.6-1.el7.centos.noarch ovirt-engine-extension-aaa-ldap-1.1.2-1.el7.centos.noarch ovirt-engine-setup-base-3.6.3.4-1.el7.centos.noarch ovirt-engine-setup-plugin-ovirt-engine-3.6.3.4-1.el7.centos.noarch ovirt-engine-setup-plugin-websocket-proxy-3.6.3.4-1.el7.centos.noarch ovirt-engine-vmconsole-proxy-helper-3.6.3.4-1.el7.centos.noarch ovirt-engine-cli-3.6.2.0-1.el7.centos.noarch ovirt-host-deploy-java-1.4.1-1.el7.centos.noarch ovirt-engine-userportal-3.6.2.6-1.el7.centos.noarch ovirt-engine-webadmin-portal-3.6.2.6-1.el7.centos.noarch ovirt-guest-agent-common-1.0.11-1.el7.noarch ovirt-release36-003-1.noarch ovirt-iso-uploader-3.6.0-1.el7.centos.noarch ovirt-engine-lib-3.6.3.4-1.el7.centos.noarch ovirt-engine-sdk-python-3.6.3.0-1.el7.centos.noarch ovirt-engine-setup-plugin-vmconsole-proxy-helper-3.6.3.4-1.el7.centos.noarch ovirt-engine-websocket-proxy-3.6.3.4-1.el7.centos.noarch ovirt-log-collector-3.6.1-1.el7.centos.noarch ovirt-engine-extensions-api-impl-3.6.3.4-1.el7.centos.noarch --- FreeIPA: [root@ipa01 ~]# cat /etc/redhat-release CentOS Linux release 7.2.1511 (Core) [root@ipa01 ~]# uname -a Linux ipa01.DOMAIN.COM 3.10.0-327.10.1.el7.x86_64 #1 SMP Tue Feb 16 17:03:50 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [root@ipa01 ~]# rpm -qa | grep ipa ipa-python-4.2.0-15.el7_2.6.x86_64 ipa-client-4.2.0-15.el7_2.6.x86_64 python-libipa_hbac-1.13.0-40.el7_2.1.x86_64 python-iniparse-0.4-9.el7.noarch libipa_hbac-1.13.0-40.el7_2.1.x86_64 sssd-ipa-1.13.0-40.el7_2.1.x86_64 ipa-admintools-4.2.0-15.el7_2.6.x86_64 ipa-server-4.2.0-15.el7_2.6.x86_64 ipa-server-dns-4.2.0-15.el7_2.6.x86_64 --- Client: [root@test06 ~]# cat /etc/redhat-release CentOS Linux release 7.2.1511 (Core) [root@test06 ~]# uname -a Linux test06.DOMAIN.COM 3.10.0-327.10.1.el7.x86_64 #1 SMP Tue Feb 16 17:03:50 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [root@test06 ~]# rpm -qa | grep ipa python-libipa_hbac-1.13.0-40.el7_2.1.x86_64 python-iniparse-0.4-9.el7.noarch sssd-ipa-1.13.0-40.el7_2.1.x86_64 ipa-client-4.2.0-15.0.1.el7.centos.6.x86_64 libipa_hbac-1.13.0-40.el7_2.1.x86_64 ipa-python-4.2.0-15.0.1.el7.centos.6.x86_64 device-mapper-multipath-0.4.9-85.el7.x86_64 device-mapper-multipath-libs-0.4.9-85.el7.x86_64 [root@test06 ~]# rpm -qa | grep guest-agent qemu-guest-agent-2.3.0-4.el7.x86_64 ovirt-guest-agent-pam-module-1.0.11-1.el7.x86_64 ovirt-guest-agent-gdm-plugin-1.0.11-1.el7.noarch ovirt-guest-agent-common-1.0.11-1.el7.noarch --------------------------------------------------- Relevant logs: --- Engine: //var/log/ovirt-engine/engine 2016-03-17 15:22:10,516 INFO [org.ovirt.engine.core.bll.aaa.LoginUserCommand] (default task-22) [] Running command: LoginUserCommand internal: false. 2016-03-17 15:22:10,568 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-22) [] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User test6@DOMAIN logged in. 2016-03-17 15:22:13,795 WARN [org.ovirt.engine.core.dal.job.ExecutionMessageDirector] (default task-6) [7400ae46] The message key 'VmLogon' is missing from 'bundles/ExecutionMessages' 2016-03-17 15:22:13,839 INFO [org.ovirt.engine.core.bll.VmLogonCommand] (default task-6) [7400ae46] Running command: VmLogonCommand internal: false. Entities affected : ID: 64a84b40-6050-4a96-a59d-d557a317c38c Type: VMAction group CONNECT_TO_VM with role type USER 2016-03-17 15:22:13,842 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.VmLogonVDSCommand] (default task-6) [7400ae46] START, VmLogonVDSCommand(HostName = host01, VmLogonVDSCommandParameters:{runAsync='true', hostId='225157c0-224b-4aa6-9210-db4de7c7fc30', vmId='64a84b40-6050-4a96-a59d-d557a317c38c', domain='DOMAIN-authz', password='***', userName='test6@DOMAIN'}), log id: 2015a1e0 2016-03-17 15:22:14,848 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.VmLogonVDSCommand] (default task-6) [7400ae46] FINISH, VmLogonVDSCommand, log id: 2015a1e0 2016-03-17 15:22:15,317 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-18) [10dad788] Running command: SetVmTicketCommand internal: true. Entities affected : ID: 64a84b40-6050-4a96-a59d-d557a317c38c Type: VMAction group CONNECT_TO_VM with role type USER 2016-03-17 15:22:15,322 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-18) [10dad788] START, SetVmTicketVDSCommand(HostName = host01, SetVmTicketVDSCommandParameters:{runAsync='true', hostId='225157c0-224b-4aa6-9210-db4de7c7fc30', vmId='64a84b40-6050-4a96-a59d-d557a317c38c', protocol='SPICE', ticket='rd8avqvdBnRl', validTime='120', userName='test6', userId='10b2da3e-6401-4a09-a330-c0780bc0faef', disconnectAction='LOCK_SCREEN'}), log id: 72efb73b 2016-03-17 15:22:16,340 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-18) [10dad788] FINISH, SetVmTicketVDSCommand, log id: 72efb73b 2016-03-17 15:22:16,377 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-18) [10dad788] Correlation ID: 10dad788, Call Stack: null, Custom Event ID: -1, Message: User test6@DOMAIN initiated console session for VM test06 2016-03-17 15:22:19,418 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-53) [] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User test6@DOMAIN-authz is connected to VM test06. --- Client: /var/log/ovirt-guest-agent/ovirt-guest-agent.log MainThread::INFO::2016-03-17 15:20:58,145::ovirt-guest-agent::57::root::Starting oVirt guest agent CredServer::INFO::2016-03-17 15:20:58,214::CredServer::257::root::CredServer is running... Dummy-1::INFO::2016-03-17 15:20:58,216::OVirtAgentLogic::294::root::Received an external command: lock-screen... Dummy-1::INFO::2016-03-17 15:22:13,104::OVirtAgentLogic::294::root::Received an external command: login... Dummy-1::INFO::2016-03-17 15:22:13,104::CredServer::207::root::The following users are allowed to connect: [0] Dummy-1::INFO::2016-03-17 15:22:13,104::CredServer::273::root::Opening credentials channel... Dummy-1::INFO::2016-03-17 15:22:13,105::CredServer::132::root::Emitting user authenticated signal (651416). CredChannel::INFO::2016-03-17 15:22:13,188::CredServer::225::root::Incomming connection from user: 0 process: 2570 CredChannel::INFO::2016-03-17 15:22:13,188::CredServer::232::root::Sending user's credential (token: 651416) Dummy-1::INFO::2016-03-17 15:22:13,189::CredServer::277::root::Credentials channel was closed. /var/log/secure Mar 17 15:21:07 test06 gdm-launch-environment]: pam_unix(gdm-launch-environment:session): session opened for user gdm by (uid=0) Mar 17 15:21:10 test06 polkitd[749]: Registered Authentication Agent for unix-session:c1 (system bus name :1.34 [gnome-shell --mode=gdm], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) Mar 17 15:22:13 test06 gdm-ovirtcred]: pam_sss(gdm-ovirtcred:auth): authentication failure; logname= uid=0 euid=0 tty= ruser= rhost= user=test6 *Mar 17 15:22:13 test06 gdm-ovirtcred]: pam_sss(gdm-ovirtcred:auth): received for user test6: 17 (Failure setting user credentials)* /var/log/sssd/krb5_child.log (debug-level 10) *(Thu Mar 17 15:22:13 2016) [[sssd[krb5_child[2575]]]] [get_and_save_tgt] (0x0020): 1234: [-1765328360][Preauthentication failed]* *(Thu Mar 17 15:22:13 2016) [[sssd[krb5_child[2575]]]] [map_krb5_error] (0x0020): 1303: [-1765328360][Preauthentication failed]* *(Thu Mar 17 15:22:13 2016) [[sssd[krb5_child[2575]]]] [k5c_send_data] (0x0200): Received error code 1432158215* (Thu Mar 17 15:22:13 2016) [[sssd[krb5_child[2575]]]] [pack_response_packet] (0x2000): response packet size: [4] (Thu Mar 17 15:22:13 2016) [[sssd[krb5_child[2575]]]] [k5c_send_data] (0x4000): Response sent. (Thu Mar 17 15:22:13 2016) [[sssd[krb5_child[2575]]]] [main] (0x0400): krb5_child completed successfully /var/log/sssd/sssd_DOMAIN.COM.log (debug-level 10) (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [be_pam_handler] (0x0100): Got request with the following data (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): domain: DOMAIN.COM (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): user: test6 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): service: gdm-ovirtcred (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): tty: (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): ruser: (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): rhost: (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): authtok type: 1 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): newauthtok type: 0 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): priv: 1 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): cli_pid: 2570 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [pam_print_data] (0x0100): logon name: not set (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [test6] is empty, running request [0x7fe30df03cc0] immediately. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [krb5_setup] (0x4000): No mapping for: test6 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fe30df07120 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fe30df16590 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ldb] (0x4000): Running timer event 0x7fe30df07120 "ltdb_callback" (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ldb] (0x4000): Destroying timer event 0x7fe30df16590 "ltdb_timeout" (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ldb] (0x4000): Ending timer event 0x7fe30df07120 "ltdb_callback" (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [get_server_status] (0x1000): Status of server 'ipa01.DOMAIN.COM' is 'working' (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [get_port_status] (0x1000): Port status of port 389 for server 'ipa01.DOMAIN.COM' is 'working' (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [resolve_srv_send] (0x0200): The status of SRV lookup is resolved (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [get_server_status] (0x1000): Status of server 'ipa01.DOMAIN.COM' is 'working' (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [be_resolve_server_process] (0x0200): Found address for server ipa01.DOMAIN.COM: [10.0.1.21] TTL 1200 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://ipa01.DOMAIN.COM' (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sss_krb5_realm_has_proxy] (0x0040): profile_get_values failed. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [2575] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [child_handler_setup] (0x2000): Signal handler set up for pid [2575] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [write_pipe_handler] (0x0400): All data has been sent! (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [child_sig_handler] (0x1000): Waiting for child [2575]. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [child_sig_handler] (0x0100): child [2575] finished successfully. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [read_pipe_handler] (0x0400): EOF received, client finished (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [check_wait_queue] (0x1000): Wait queue for user [test6] is empty. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x7fe30df03cc0] done. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_id_op_connect_step] (0x4000): reusing cached connection (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_print_server] (0x2000): Searching 10.0.1.21 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=ipaConfig)(objectClass=ipaGuiConfig))][cn=etc,dc=DOMAIN,dc=com]. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaMigrationEnabled] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSELinuxUserMapDefault] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSELinuxUserMapOrder] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 122 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_op_add] (0x2000): New operation 122 timeout 60 (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_process_result] (0x2000): Trace: sh[0x7fe30deef090], connected[1], ops[0x7fe30df094a0], ldap[0x7fe30def2920] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=ipaConfig,cn=etc,dc=DOMAIN,dc=com]. (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaMigrationEnabled] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaSELinuxUserMapDefault] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaSELinuxUserMapOrder] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_process_result] (0x2000): Trace: sh[0x7fe30deef090], connected[1], ops[0x7fe30df094a0], ldap[0x7fe30def2920] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_op_destructor] (0x2000): Operation 122 finished (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [ipa_get_migration_flag_done] (0x0100): Password migration is not enabled. *(Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 17, <NULL>) [Success (Failure setting user credentials)] * (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [be_pam_handler_callback] (0x0100): Sending result [17][DOMAIN.COM] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [be_pam_handler_callback] (0x0100): Sent result [17][DOMAIN.COM] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_process_result] (0x2000): Trace: sh[0x7fe30deef090], connected[1], ops[(nil)], ldap[0x7fe30def2920] (Thu Mar 17 15:22:13 2016) [sssd[be[DOMAIN.COM]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! _______________________________________________ Users mailing list Users(a)ovirt.org http://lists.ovirt.org/mailman/listinfo/users