[SSSD-users] 1.12 beta can't authenticate

Lukas Slebodnik lslebodn at redhat.com
Sat May 31 14:53:31 UTC 2014


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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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:steve2 at hh3.site]
>(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:steve2 at hh3.site]
>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
>$@HH3.SITE]
>(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 [steve2 at HH3.SITE] 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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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:steve2 at hh3.site]
>(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 [steve2 at HH3.SITE]
>(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/catral.hh3.site at HH3.SITE].
>(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\@HH3.SITE at HH3.SITE] 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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(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 [steve2 at hh3.site]
>(Sat May 31 16:25:29 2014) [sssd[pam]] [pam_check_user_search] (0x0400):
>Returning info for user [steve2 at hh3.site]
>(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


More information about the sssd-users mailing list