On (31/05/14 16:42), steve wrote: >Hi >can kinit OK but pam doesn't allow us in it seems. >Any ideas? >Thanks >Steve >--- --- --- > >openSUSE 13.1 >make install of beta build over a working 1.11.5.1 > >Here is a domain user: > id steve2 >uid=3000021(steve2) gid=20513(domain users) grupos=20513(domain >users),21111(staff2) > >steve2 can authenticate and su fine with 1.11.5.1 on the same client > >pam: >auth required pam_env.so >auth optional pam_gnome_keyring.so >auth sufficient pam_unix.so try_first_pass >auth required pam_sss.so use_first_pass > >client log: >2014-05-31T16:25:27.738959+02:00 catral su: pam_unix(su:auth): >authentication failure; logname=steve uid=1000 euid=0 tty=pts/1 >ruser=steve rhost= user=steve2 >2014-05-31T16:25:29.102746+02:00 catral su: pam_sss(su:auth): >authentication success; logname=steve uid=1000 euid=0 tty=pts/1 >ruser=steve rhost= user=steve2 >2014-05-31T16:25:29.164275+02:00 catral su: pam_sss(su:account): Access >denied for user steve2: 4 (Error del sistema) > >sssd -i -d7: >2014-05-31T16:25:07.537030+02:00 catral sssd: Starting up >2014-05-31T16:25:07.854951+02:00 catral sssd[be[hh3.site]]: Starting up >2014-05-31T16:25:09.645973+02:00 catral sssd[pam]: Starting up >2014-05-31T16:25:09.665278+02:00 catral sssd[nss]: Starting up >2014-05-31T16:25:09.702723+02:00 catral sssd[autofs]: Starting up > >(Sat May 31 16:25:24 2014) [sssd[nss]] [accept_fd_handler] (0x0400): >Client connected! >(Sat May 31 16:25:24 2014) [sssd[nss]] [sss_cmd_get_version] (0x0200): >Received client version [1]. >(Sat May 31 16:25:24 2014) [sssd[nss]] [sss_cmd_get_version] (0x0200): >Offered version [1]. >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0400): >Running command [17] with input [steve2]. >(Sat May 31 16:25:24 2014) [sssd[nss]] [sss_parse_name_for_domains] >(0x0200): name 'steve2' matched without domain, user is steve2 >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0100): >Requesting info for [steve2] from [<ALL>] >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0100): Requesting info for [[email protected]] >(Sat May 31 16:25:24 2014) [sssd[nss]] [check_cache] (0x0400): Cached >entry is valid, returning.. >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0400): Returning info for user [[email protected]] >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0400): >Running command [17] with input [steve2]. >(Sat May 31 16:25:24 2014) [sssd[nss]] [sss_parse_name_for_domains] >(0x0200): name 'steve2' matched without domain, user is steve2 >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0100): >Requesting info for [steve2] from [<ALL>] >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0100): Requesting info for [[email protected]] >(Sat May 31 16:25:24 2014) [sssd[nss]] [check_cache] (0x0400): Cached >entry is valid, returning.. >(Sat May 31 16:25:24 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0400): Returning info for user [[email protected]] >(Sat May 31 16:25:27 2014) [sssd] [service_send_ping] (0x0100): Pinging >hh3.site >(Sat May 31 16:25:27 2014) [sssd] [ping_check] (0x0100): Service >hh3.site replied to ping >(Sat May 31 16:25:27 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0400): >Running command [17] with input [steve2]. >(Sat May 31 16:25:27 2014) [sssd[nss]] [sss_parse_name_for_domains] >(0x0200): name 'steve2' matched without domain, user is steve2 >(Sat May 31 16:25:27 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0100): >Requesting info for [steve2] from [<ALL>] >(Sat May 31 16:25:27 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0100): Requesting info for [[email protected]] >(Sat May 31 16:25:27 2014) [sssd[nss]] [check_cache] (0x0400): Cached >entry is valid, returning.. >(Sat May 31 16:25:27 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0400): Returning info for user [[email protected]] >(Sat May 31 16:25:27 2014) [sssd[pam]] [accept_fd_handler] (0x0400): >Client connected! >(Sat May 31 16:25:27 2014) [sssd[pam]] [sss_cmd_get_version] (0x0200): >Received client version [3]. >(Sat May 31 16:25:27 2014) [sssd[pam]] [sss_cmd_get_version] (0x0200): >Offered version [3]. >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_cmd_authenticate] (0x0100): >entering pam_cmd_authenticate >(Sat May 31 16:25:27 2014) [sssd[pam]] [sss_parse_name_for_domains] >(0x0200): name 'steve2' matched without domain, user is steve2 >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): >command: PAM_AUTHENTICATE >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): >domain: not set >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): user: >steve2 >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): >service: su >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: >pts/1 >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): ruser: >steve >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): rhost: >not set >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): >authtok type: 1 >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): >newauthtok type: 0 >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: >0 >(Sat May 31 16:25:27 2014) [sssd[pam]] [pam_print_data] (0x0100): >cli_pid: 2423 >(Sat May 31 16:25:27 2014) [sssd[pam]] [sss_dp_issue_request] (0x0400): >Issuing request for [0x8054300:3:[email protected]] >(Sat May 31 16:25:27 2014) [sssd[pam]] [sss_dp_get_account_msg] >(0x0400): Creating request for [hh3.site][3][1][name=steve2] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [be_get_account_info] >(0x0100): Got request for [3][1][name=steve2] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [be_req_set_domain] >(0x0400): Changing request domain from [hh3.site] to [hh3.site] >(Sat May 31 16:25:27 2014) [sssd[pam]] [sss_dp_internal_get_send] >(0x0400): (Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[fo_resolve_service_send] (0x0100): Entering request >[0x8054300:3:[email protected]] >Trying to resolve service 'AD_GC' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [get_server_status] >(0x1000): Status of server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [get_port_status] >(0x1000): Port status of port 0 for server 'hh16.hh3.site' is 'neutral' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [get_server_status] >(0x1000): Status of server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[be_resolve_server_process] (0x1000): Saving the first resolved server >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[be_resolve_server_process] (0x0200): Found address for server >hh16.hh3.site: [192.168.1.16] TTL 7200 >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [ad_resolve_callback] >(0x0100): Constructed uri 'ldap://hh16.hh3.site' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [ad_resolve_callback] >(0x0100): Constructed GC uri 'ldap://hh16.hh3.site:3268' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [sss_ldap_init_send] >(0x0400): Setting 6 seconds timeout for connecting >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to >[ldap://hh16.hh3.site:3268/??base] with fd [18]. >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with >[(objectclass=*)][]. >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[supportedControl] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[supportedExtension] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[supportedFeatures] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[supportedLDAPVersion] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[supportedSASLMechanisms] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[domainControllerFunctionality] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[defaultNamingContext] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[highestCommittedUSN] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no >errmsg set >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_get_server_opts_from_rootdse] (0x0100): Setting AD compatibility >level to [4] >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [sdap_kinit_send] >(0x0400): Attempting kinit (/etc/krb5.keytab, CATRAL$, HH3.SITE, 86400) >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [sdap_kinit_next_kdc] >(0x1000): Resolving next KDC for service AD >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [get_server_status] >(0x1000): Status of server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [get_port_status] >(0x1000): Port status of port 0 for server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [get_server_status] >(0x1000): Status of server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[be_resolve_server_process] (0x1000): Saving the first resolved server >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[be_resolve_server_process] (0x0200): Found address for server >hh16.hh3.site: [192.168.1.16] TTL 7200 >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [ad_resolve_callback] >(0x0100): Constructed uri 'ldap://hh16.hh3.site' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [ad_resolve_callback] >(0x0100): Constructed GC uri 'ldap://hh16.hh3.site' >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[sdap_kinit_kdc_resolved] (0x1000): KDC resolved, attempting to get >TGT... >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] >[create_tgt_req_send_buffer] (0x0400): buffer size: 47 >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [set_tgt_child_timeout] >(0x0400): Setting 6 seconds timeout for tgt child >(Sat May 31 16:25:27 2014) [sssd[be[hh3.site]]] [write_pipe_handler] >(0x0400): All data has been sent! >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [main] (0x0400): >ldap_child started. >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): total buffer size: 47 >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): realm_str size: 8 >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): got realm_str: HH3.SITE >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): princ_str size: 7 >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): got princ_str: CATRAL$ >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): keytab_name size: 16 >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): got keytab_name: /etc/krb5.keytab >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] [unpack_buffer] >(0x1000): lifetime: 86400 >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] >[ldap_child_get_tgt_sync] (0x0100): Principal name is: [CATRAL >[email protected]] >(Sat May 31 16:25:27 2014) [[sssd[ldap_child[2424]]]] >[ldap_child_get_tgt_sync] (0x0100): Using keytab [/etc/krb5.keytab] >(Sat May 31 16:25:28 2014) [sssd] [service_send_ping] (0x0100): Pinging >nss >(Sat May 31 16:25:28 2014) [sssd] [service_send_ping] (0x0100): Pinging >pam >(Sat May 31 16:25:28 2014) [sssd] [service_send_ping] (0x0100): Pinging >autofs >(Sat May 31 16:25:28 2014) [sssd] [ping_check] (0x0100): Service autofs >replied to ping >(Sat May 31 16:25:28 2014) [sssd] [ping_check] (0x0100): Service pam >replied to ping >(Sat May 31 16:25:28 2014) [[sssd[ldap_child[2424]]]] [prepare_response] >(0x0400): (Sat May 31 16:25:28 2014) [sssd] [ping_check] (0x0100): >Service nss replied to ping >Building response for result [0] >(Sat May 31 16:25:28 2014) [[sssd[ldap_child[2424]]]] [pack_buffer] >(0x1000): result [0] krberr [0] msgsize [46] msg >[FILE:/usr/local/var/lib/sss/db/ccache_HH3.SITE] >(Sat May 31 16:25:28 2014) [[sssd[ldap_child[2424]]]] [main] (0x0400): >ldap_child completed successfully >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [read_pipe_handler] >(0x0400): EOF received, client finished >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_get_tgt_recv] >(0x0400): Child responded: 0 >[FILE:/usr/local/var/lib/sss/db/ccache_HH3.SITE], expired on >[1401582327] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_cli_auth_step] >(0x0100): expire timeout is 900 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_cli_auth_step] >(0x1000): the connection will expire at 1401547228 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sasl_bind_send] >(0x0100): Executing sasl bind mech: gssapi, user: CATRAL$ >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [child_sig_handler] >(0x1000): Waiting for child [2424]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [child_sig_handler] >(0x0100): child [2424] finished successfully. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [fo_set_port_status] >(0x0100): Marking port 0 of server 'hh16.hh3.site' as 'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[set_server_common_status] (0x0100): Marking server 'hh16.hh3.site' as >'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [ad_user_data_cmp] >(0x1000): Comparing GC with GC >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [fo_set_port_status] >(0x0400): Marking port 0 of duplicate server 'hh16.hh3.site' as >'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_initgr_next_base] (0x0400): Searching for users with base >[DC=hh3,DC=site] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with >[(&(sAMAccountName=steve2)(objectclass=user)(&(uidNumber=*)(!(uidNumber=0))))][DC=hh3,DC=site]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [sAMAccountName] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[unixUserPassword] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uidNumber] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gecos] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[unixHomeDirectory] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [loginShell] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[userPrincipalName] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [name] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectGUID] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectSID] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [primaryGroupID] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [whenChanged] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [uSNChanged] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [accountExpires] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[userAccountControl] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no >errmsg set >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_save_user] >(0x0400): Save user >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_get_primary_name] >(0x0400): Processing object steve2 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_save_user] >(0x0400): Processing user steve2 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_save_user] >(0x0400): Adding original memberOf attributes to [steve2]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_save_user] >(0x0400): Adding user principal [[email protected]] to attributes of >[steve2]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [sdap_save_user] >(0x0400): Storing info for user steve2 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no >filter][CN=steve2,CN=Users,DC=hh3,DC=site]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: [tokenGroups] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no >errmsg set >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_ad_tokengroups_initgr_posix_tg_done] (0x1000): Processing >membership SID [S-1-5-21-451355595-2219208293-2714859210-1111] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_ad_tokengroups_initgr_posix_tg_done] (0x1000): Processing >membership SID [S-1-5-21-451355595-2219208293-2714859210-513] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_ad_tokengroups_initgr_posix_tg_done] (0x1000): Processing >membership SID [S-1-5-32-545] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_ad_tokengroups_initgr_posix_tg_done] (0x0080): Domain not found >for SID S-1-5-32-545 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[sdap_ad_tokengroups_update_members] (0x1000): Updating memberships for >[steve2] >(Sat May 31 16:25:28 2014) [sssd[nss]] [nss_memcache_initgr_check] >(0x1000): Got request for [[email protected]] >(Sat May 31 16:25:28 2014) [sssd[pam]] [sss_dp_get_reply] (0x1000): Got >reply from Data Provider - DP error code: 0 errno: 0 error message: >Success >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_check_user_search] (0x0100): >Requesting info for [[email protected]] >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_check_user_search] (0x0400): >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [acctinfo_callback] >(0x0100): Request processed. Returned 0,0,Success >Returning info for user [[email protected]] >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_dp_send_req] (0x0100): >Sending request with the following data: >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): >command: PAM_AUTHENTICATE >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): >domain: hh3.site >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): user: >steve2 >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): >service: su >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: >pts/1 >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): ruser: >steve >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): rhost: >not set >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): >authtok type: 1 >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): >newauthtok type: 0 >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: >0 >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_print_data] (0x0100): >cli_pid: 2423 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [be_req_set_domain] >(0x0400): Changing request domain from [hh3.site] to [hh3.site] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [be_pam_handler] >(0x0100): Got request with the following data >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): command: PAM_AUTHENTICATE >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): domain: hh3.site >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): user: steve2 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): service: su >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): tty: pts/1 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): ruser: steve >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): rhost: >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): authtok type: 1 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): newauthtok type: 0 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): priv: 0 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): cli_pid: 2423 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [krb5_pam_handler] >(0x1000): Wait queue of user [steve2] is empty, running request >immediately. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [switch_creds] (0x0200): >Switch user to [3000021][20513]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [switch_creds] (0x0200): >Switch user to [0][0]. >(Sat May 31 16:25:28 2014) [sssd[pam]] [pam_dom_forwarder] (0x0100): >pam_dp_send_req returned 0 >(Sat May 31 16:25:28 2014) [sssd[pam]] [sss_dp_req_destructor] (0x0400): >Deleting request: [0x8054300:3:[email protected]] >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[fo_resolve_service_send] (0x0100): Trying to resolve service 'AD' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [get_server_status] >(0x1000): Status of server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [get_port_status] >(0x1000): Port status of port 0 for server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [get_server_status] >(0x1000): Status of server 'hh16.hh3.site' is 'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[be_resolve_server_process] (0x1000): Saving the first resolved server >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[be_resolve_server_process] (0x0200): Found address for server >hh16.hh3.site: [192.168.1.16] TTL 7200 >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [ad_resolve_callback] >(0x0100): Constructed uri 'ldap://hh16.hh3.site' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [ad_resolve_callback] >(0x0100): Constructed GC uri 'ldap://hh16.hh3.site' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [write_pipe_handler] >(0x0400): All data has been sent! >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [main] (0x0400): >krb5_child started. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [unpack_buffer] >(0x1000): total buffer size: [106] >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [unpack_buffer] >(0x0100): cmd [241] uid [3000021] gid [20513] validate [true] enterprise >principal [true] offline [false] UPN [[email protected]] >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [unpack_buffer] >(0x0100): ccname: [FILE:/tmp/krb5cc_3000021] keytab: [/etc/krb5.keytab] >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] >[set_lifetime_options] (0x0100): Cannot read >[SSSD_KRB5_RENEWABLE_LIFETIME] from environment. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] >[set_lifetime_options] (0x0100): Cannot read [SSSD_KRB5_LIFETIME] from >environment. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] >[set_canonicalize_option] (0x0100): SSSD_KRB5_CANONICALIZE is set to >[true] >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [k5c_setup] >(0x0100): Not using FAST. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [main] (0x0400): >Will perform online auth >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [tgt_req_child] >(0x1000): Attempting to get a TGT >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [get_and_save_tgt] >(0x0400): Attempting kinit for realm [HH3.SITE] >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [validate_tgt] >(0x0400): TGT verified using key for [host/[email protected]]. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [sss_send_pac] >(0x0040): sss_pac_make_request failed [-1][2]. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [validate_tgt] >(0x0040): sss_send_pac failed, group membership for user with principal >[steve2\@[email protected]] might not be correct. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [become_user] >(0x0200): Trying to become user [3000021][20513]. >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [k5c_send_data] >(0x0200): Received error code 0 >(Sat May 31 16:25:28 2014) [[sssd[krb5_child[2425]]]] [main] (0x0400): >krb5_child completed successfully >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [read_pipe_handler] >(0x0400): EOF received, client finished >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[parse_krb5_child_response] (0x1000): child response [0][3][36]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[parse_krb5_child_response] (0x1000): child response >[0][-1073741822][16]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[parse_krb5_child_response] (0x1000): child response >[0][-1073741823][32]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[parse_krb5_child_response] (0x1000): TGT times are >[1401546329][1401546329][1401582329][1401632728]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [fo_set_port_status] >(0x0100): Marking port 0 of server 'hh16.hh3.site' as 'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[set_server_common_status] (0x0100): Marking server 'hh16.hh3.site' as >'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [ad_user_data_cmp] >(0x1000): Comparing LDAP with LDAP >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [fo_set_port_status] >(0x0400): Marking port 0 of duplicate server 'hh16.hh3.site' as >'working' >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [switch_creds] (0x0200): >Switch user to [3000021][20513]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] [switch_creds] (0x0200): >Switch user to [0][0]. >(Sat May 31 16:25:28 2014) [sssd[be[hh3.site]]] >[safe_remove_old_ccache_file] (0x0400): New and old ccache file are the >same, none will be deleted. >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [check_wait_queue] >(0x1000): Wait queue for user [steve2] is empty. >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>) >[Success] >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[be_pam_handler_callback] (0x0100): Sending result [0][hh3.site] >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_dp_process_reply] (0x0100): >received: [0][hh3.site] >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_reply] (0x0200): pam_reply >called with result [0]. >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_reply] (0x0200): blen: 69 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[be_pam_handler_callback] (0x0100): (Sat May 31 16:25:29 2014) >[sssd[nss]] [nss_cmd_getbynam] (0x0400): Running command [17] with input >[steve2]. >(Sat May 31 16:25:29 2014) [sssd[nss]] [sss_parse_name_for_domains] >(0x0200): name 'steve2' matched without domain, user is steve2 >(Sat May 31 16:25:29 2014) [sssd[nss]] [nss_cmd_getbynam] (0x0100): >Requesting info for [steve2] from [<ALL>] >(Sat May 31 16:25:29 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0100): Requesting info for [[email protected]] >(Sat May 31 16:25:29 2014) [sssd[nss]] [check_cache] (0x0400): Cached >entry is valid, returning.. >(Sat May 31 16:25:29 2014) [sssd[nss]] [nss_cmd_getpwnam_search] >(0x0400): Returning info for user [[email protected]] >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_cmd_acct_mgmt] (0x0100): >Sent result [0][hh3.site] >entering pam_cmd_acct_mgmt >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [child_sig_handler] >(0x1000): (Sat May 31 16:25:29 2014) [sssd[pam]] >[sss_parse_name_for_domains] (0x0200): Waiting for child [2425]. >name 'steve2' matched without domain, user is steve2 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): (Sat >May 31 16:25:29 2014) [sssd[be[hh3.site]]] [child_sig_handler] (0x0100): >command: PAM_ACCT_MGMT >child [2425] finished successfully. >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >domain: not set >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): user: >steve2 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >service: su >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: >pts/1 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): ruser: >steve >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): rhost: >not set >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >authtok type: 0 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >newauthtok type: 0 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: >0 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >cli_pid: 2423 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_check_user_search] (0x0100): >Requesting info for [[email protected]] >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_check_user_search] (0x0400): >Returning info for user [[email protected]] >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_dp_send_req] (0x0100): >Sending request with the following data: >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >command: PAM_ACCT_MGMT >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >domain: hh3.site >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): user: >steve2 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >service: su >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): tty: >pts/1 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): ruser: >steve >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): rhost: >not set >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >authtok type: 0 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >newauthtok type: 0 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): priv: >0 >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_print_data] (0x0100): >cli_pid: 2423 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [be_req_set_domain] >(0x0400): Changing request domain from [hh3.site] to [hh3.site] >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [be_pam_handler] >(0x0100): Got request with the following data >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): command: PAM_ACCT_MGMT >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): domain: hh3.site >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): user: steve2 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): service: su >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): tty: pts/1 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): ruser: steve >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): rhost: >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): authtok type: 0 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): newauthtok type: 0 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): priv: 0 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [pam_print_data] >(0x0100): cli_pid: 2423 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [sdap_access_send] >(0x0400): Performing access check for user [steve2] >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[sdap_account_expired_ad] (0x0400): Performing AD access check for user >[steve2] >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [ad_gpo_connect_done] >(0x0400): sam_account_name is catral.hh3.site$ >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with >[(&(objectclass=user)(sAMAccountName=catral.hh3.site >$))][dc=hh3,dc=site]. >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[distinguishedName] >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_step] (0x1000): Requesting attrs: >[userAccountControl] >(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_dom_forwarder] (0x0100): >pam_dp_send_req returned 0 >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no >errmsg set >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] >[ad_gpo_target_dn_retrieval_done] (0x0040): No DN retrieved for policy >target. >(Sat May 31 16:25:29 2014) [sssd[be[hh3.site]]] [ad_gpo_access_done] >(0x0040): GPO-based access control failed. ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ You can change value of option ad_gpo_access_control to disable. Default value is permissive. I would say it is a bug that we fail in permissive mode. Details are in manual page sssd-ad.
LS _______________________________________________ sssd-users mailing list [email protected] https://lists.fedorahosted.org/mailman/listinfo/sssd-users
