Bug 707999

Summary: The IPA provider does not work with IPv6
Product: Red Hat Enterprise Linux 5 Reporter: Jakub Hrozek <jhrozek>
Component: sssdAssignee: Stephen Gallagher <sgallagh>
Status: CLOSED ERRATA QA Contact: Chandrasekar Kannan <ckannan>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 5.7CC: benl, dpal, grajaiya, jgalipea, prc
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: sssd-1.5.1-38.el5 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 707997 Environment:
Last Closed: 2012-02-21 06:22:52 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 707997    
Bug Blocks:    

Description Jakub Hrozek 2011-05-26 14:12:17 UTC 
+++ This bug was initially created as a clone of Bug #707997 +++

Description of problem:
The IP provider of SSSD fails to connect to an IPA server if the IPA server hostname resolves to an IPv6 address.

Version-Release number of selected component (if applicable):
1.5.1-37

How reproducible:
always

Steps to Reproduce:
1. configure IPA backend so that ipa_server points to a hostname that resolves to an IPv6 address
2. start sssd
3. try to get user info, e.g. getent passwd admin
  
Actual results:
Nothing is returned, sssd goes offline.

Expected results:
sssd connects and returns the user

Additional info:
The problem is that in the resolve callback we construct the LDAP URI based on IP address. LDAP routines cannot parse IPv6 IP address in URI.

We should use the server hostname instead.

When you hit the bug, the logs would show something like this:
[sdap_connect_send] (1): ldap_initialize failed: Bad parameter to an ldap routine

--- Additional comment from jhrozek on 2011-05-26 10:10:10 EDT ---

Upstream ticket:
https://fedorahosted.org/sssd/ticket/880
Comment 2 Stephen Gallagher 2011-09-30 12:33:01 UTC 
Upstream ticket:
https://fedorahosted.org/sssd/ticket/880
Comment 3 Gowrishankar Rajaiyan 2012-01-10 11:05:06 UTC 
Server:
[root@jetfire ~]# ifconfig eth0
eth0      Link encap:Ethernet  HWaddr 52:54:00:A8:B6:69  
          inet6 addr: 2620:52:0:41c9:5054:ff:fea8:b669/64 Scope:Global
          inet6 addr: fe80::5054:ff:fea8:b669/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:150910 errors:0 dropped:0 overruns:0 frame:0
          TX packets:13182 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:74030720 (70.6 MiB)  TX bytes:1810825 (1.7 MiB)

[root@jetfire ~]# 

[root@jetfire ~]# service ipa status
Directory Service: RUNNING
KDC Service: RUNNING
KPASSWD Service: RUNNING
DNS Service: RUNNING
HTTP Service: RUNNING
CA Service: RUNNING
[root@jetfire ~]# 


[root@jetfire ~]# ipa user-add shanks --first=Gowrishankar --last=Rajaiyan --password
Password: 
Enter Password again to verify: 
-------------------
Added user "shanks"
-------------------
  User login: shanks
  First name: Gowrishankar
  Last name: Rajaiyan
  Full name: Gowrishankar Rajaiyan
  Display name: Gowrishankar Rajaiyan
  Initials: GR
  Home directory: /home/shanks
  GECOS field: Gowrishankar Rajaiyan
  Login shell: /bin/sh
  Kerberos principal: shanks.PNQ.REDHAT.COM
  UID: 1001200003
  GID: 1001200003
  Keytab: True
  Password: True
[root@jetfire ~]# 


Client:
[root@ratchet ~]# ifconfig eth0
eth0      Link encap:Ethernet  HWaddr 52:54:00:A6:0E:C8  
          inet6 addr: 2620:52:0:41c9:5054:ff:fea6:ec8/64 Scope:Global
          inet6 addr: fe80::5054:ff:fea6:ec8/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:19074 errors:0 dropped:0 overruns:0 frame:0
          TX packets:1002 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:1477222 (1.4 MiB)  TX bytes:197635 (193.0 KiB)

[root@ratchet ~]# 

[root@ratchet ~]# ipa-client-install 
Discovery was successful!
Hostname: ratchet.lab.eng.pnq.redhat.com
Realm: LAB.ENG.PNQ.REDHAT.COM
DNS Domain: lab.eng.pnq.redhat.com
IPA Server: jetfire.lab.eng.pnq.redhat.com
BaseDN: dc=lab,dc=eng,dc=pnq,dc=redhat,dc=com

Continue to configure the system with these values? [no]: yes
User authorized to enroll computers: admin
Synchronizing time with KDC...
Unable to sync time with IPA NTP server, assuming the time is in sync.
Password for admin.PNQ.REDHAT.COM: 

Enrolled in IPA realm LAB.ENG.PNQ.REDHAT.COM
Created /etc/ipa/default.conf
Configured /etc/sssd/sssd.conf
Configured /etc/krb5.conf for IPA realm LAB.ENG.PNQ.REDHAT.COM
SSSD enabled
NTP enabled
Client configuration complete.
[root@ratchet ~]# 


Client:

[root@ratchet ~]# getent -s sss passwd shanks
shanks:*:1001200003:1001200003:Gowrishankar Rajaiyan:/home/shanks:/bin/sh
[root@ratchet ~]# 


(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_dispatch] (9): dbus conn: D613510
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_dispatch] (9): Dispatching.
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [be_get_account_info] (4): Got request for [4097][1][name=shanks]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_step] (9): beginning to connect
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'IPA'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [get_port_status] (7): Port status of port 0 for server '(no name)' is 'neutral'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolve_srv_send] (6): The status of SRV lookup is neutral
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolve_get_domain_send] (7): Host name is: ratchet.lab.eng.pnq.redhat.com
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_is_address] (9): [ratchet.lab.eng.pnq.redhat.com] does not look like an IP address
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_step] (8): Querying files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_files_send] (4): Trying to resolve A record of 'ratchet.lab.eng.pnq.redhat.com' in files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_step] (8): Querying files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_files_send] (4): Trying to resolve AAAA record of 'ratchet.lab.eng.pnq.redhat.com' in files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolve_get_domain_done] (7): The full FQDN is: ratchet.lab.eng.pnq.redhat.com
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolve_srv_cont] (4): Searching for servers via SRV query '_ldap._tcp.lab.eng.pnq.redhat.com'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_getsrv_send] (4): Trying to resolve SRV record of '_ldap._tcp.lab.eng.pnq.redhat.com'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [schedule_timeout_watcher] (9): Scheduling DNS timeout watcher
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [unschedule_timeout_watcher] (9): Unscheduling DNS timeout watcher
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolve_srv_done] (6): Inserted server 'jetfire.lab.eng.pnq.redhat.com:389' for service IPA
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [set_srv_data_status] (4): Marking SRV lookup of service 'IPA' as 'resolved'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name not resolved'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_is_address] (9): [jetfire.lab.eng.pnq.redhat.com] does not look like an IP address
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_step] (8): Querying files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_files_send] (4): Trying to resolve A record of 'jetfire.lab.eng.pnq.redhat.com' in files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [set_server_common_status] (4): Marking server 'jetfire.lab.eng.pnq.redhat.com' as 'resolving name'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_step] (8): Querying files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [resolv_gethostbyname_files_send] (4): Trying to resolve AAAA record of 'jetfire.lab.eng.pnq.redhat.com' in files
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [set_server_common_status] (4): Marking server 'jetfire.lab.eng.pnq.redhat.com' as 'name resolved'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [be_resolve_server_done] (4): Found address for server jetfire.lab.eng.pnq.redhat.com: [2620:52:0:41c9:5054:ff:fea8:b669] TTL 7200
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ipa_resolve_callback] (6): Constructed uri 'ldap://jetfire.lab.eng.pnq.redhat.com'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sss_ldap_init_send] (9): Using file descriptor [26] for LDAP connection.
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sss_ldap_init_send] (6): Setting 6 seconds timeout for connecting
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_ldap_connect_callback_add] (9): New LDAP connection to [ldap://jetfire.lab.eng.pnq.redhat.com:389/??base] with fd [26].
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_rootdse_send] (9): Getting rootdse
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(objectclass=*)][].
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [*]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [altServer]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [namingContexts]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedControl]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedExtension]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedFeatures]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedLDAPVersion]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [supportedSASLMechanisms]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [defaultNamingContext]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [lastUSN]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [highestCommittedUSN]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 1
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0xd618bc0], connected[1], ops[0xd622990], ldap[0xd619300]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_parse_entry] (9): OriginalDN: [].
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0xd618bc0], connected[1], ops[0xd622990], ldap[0xd619300]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_rootdse_done] (9): Got rootdse
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_kinit_send] (6): Attempting kinit ((null), host/ratchet.lab.eng.pnq.redhat.com, LAB.ENG.PNQ.REDHAT.COM, 86400)
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_kinit_next_kdc] (7): Resolving next KDC for service IPA
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_resolve_service_send] (4): Trying to resolve service 'IPA'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [get_port_status] (7): Port status of port 0 for server 'jetfire.lab.eng.pnq.redhat.com' is 'neutral'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [get_server_status] (7): Status of server 'jetfire.lab.eng.pnq.redhat.com' is 'name resolved'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [be_resolve_server_done] (4): Found address for server jetfire.lab.eng.pnq.redhat.com: [2620:52:0:41c9:5054:ff:fea8:b669] TTL 7200
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ipa_resolve_callback] (6): Constructed uri 'ldap://jetfire.lab.eng.pnq.redhat.com'
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_kinit_kdc_resolved] (7): KDC resolved, attempting to get TGT...
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [create_tgt_req_send_buffer] (7): buffer size: 73
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [child_handler_setup] (8): Setting up signal handler up for pid [3456]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [child_handler_setup] (8): Signal handler set up for pid [3456]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [set_tgt_child_timeout] (6): Setting 6 seconds timeout for tgt child
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0xd618bc0], connected[1], ops[(nil)], ldap[0xd619300]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [write_pipe_handler] (6): All data has been sent!
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [read_pipe_handler] (6): EOF received, client finished
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_tgt_recv] (6): Child responded: 0 [FILE:/var/lib/sss/db/ccache_LAB.ENG.PNQ.REDHAT.COM], expired on [1326279657]
(Tue Jan 10 06:01:08 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sasl_bind_send] (4): Executing sasl bind mech: GSSAPI, user: host/ratchet.lab.eng.pnq.redhat.com
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [child_sig_handler] (7): Waiting for child [3456].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [child_sig_handler] (4): child [3456] finished successfully.
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [fo_set_port_status] (4): Marking port 389 of server 'jetfire.lab.eng.pnq.redhat.com' as 'working'
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [set_server_common_status] (4): Marking server 'jetfire.lab.eng.pnq.redhat.com' as 'working'
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_done] (9): notify connected to op #1
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (6): calling ldap_search_ext with [(&(uid=shanks)(objectclass=posixAccount))][cn=accounts,dc=lab,dc=eng,dc=pnq,dc=redhat,dc=com].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [objectClass]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [uid]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [userPassword]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [uidNumber]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [gidNumber]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [gecos]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [homeDirectory]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [loginShell]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [krbPrincipalName]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [cn]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [memberOf]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [nsUniqueId]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [modifyTimestamp]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowLastChange]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowMin]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowMax]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowWarning]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowInactive]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowExpire]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [shadowFlag]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [krbLastPwdChange]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [krbPasswordExpiration]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [pwdAttribute]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [authorizedService]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [accountExpires]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [userAccountControl]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (7): Requesting attrs: [nsAccountLock]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_step] (8): ldap_search_ext called, msgid = 5
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_connect_done] (9): caching successful connection after 1 notifies
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [be_run_online_cb] (3): Going online. Running callbacks.
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0xd618bc0], connected[1], ops[0xd623850], ldap[0xd619300]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_parse_entry] (9): OriginalDN: [uid=shanks,cn=users,cn=accounts,dc=lab,dc=eng,dc=pnq,dc=redhat,dc=com].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0xd618bc0], connected[1], ops[0xd623850], ldap[0xd619300]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_generic_done] (7): Total count [0]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_users_process] (6): Search for users, returned 1 results.
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): start ldb transaction (nesting: 0)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (9): Save user
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (7): Adding original DN [uid=shanks,cn=users,cn=accounts,dc=lab,dc=eng,dc=pnq,dc=redhat,dc=com] to attributes of [shanks].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (7): Adding original memberOf attributes to [shanks].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (7): Original USN value is not available for [shanks].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (7): Adding user principal [shanks.PNQ.REDHAT.COM] to attributes of [shanks].
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (9): Adding [krbLastPwdChange]=[20120110105955Z] to user attributes.
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (9): Adding [krbPasswordExpiration]=[20120110105955Z] to user attributes.
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_user] (6): Storing info for user shanks
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): start ldb transaction (nesting: 1)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0xd630120

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0xd630240

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Destroying timer event 0xd630240 "ltdb_timeout"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Ending timer event 0xd630120 "ltdb_callback"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sysdb_search_user_by_name] (6): Error: 2 (No such file or directory)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): start ldb transaction (nesting: 2)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0xd625ec0

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0xd625fe0

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Destroying timer event 0xd625fe0 "ltdb_timeout"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Ending timer event 0xd625ec0 "ltdb_callback"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sysdb_search_user_by_uid] (6): Error: 2 (No such file or directory)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): start ldb transaction (nesting: 3)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0xd63cda0

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0xd63cec0

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Destroying timer event 0xd63cec0 "ltdb_timeout"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Ending timer event 0xd63cda0 "ltdb_callback"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): commit ldb transaction (nesting: 3)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): start ldb transaction (nesting: 3)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_callback": 0xd63d080

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Added timed event "ltdb_timeout": 0xd63d1a0

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Destroying timer event 0xd63d1a0 "ltdb_timeout"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): tevent: Ending timer event 0xd63d080 "ltdb_callback"

(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): commit ldb transaction (nesting: 3)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): commit ldb transaction (nesting: 2)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): commit ldb transaction (nesting: 1)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_save_users] (9): User 0 processed!
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [ldb] (9): commit ldb transaction (nesting: 0)
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_get_users_process] (9): Saving 1 Users - Done
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_id_op_done] (9): releasing operation connection
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [acctinfo_callback] (4): Request processed. Returned 0,0,Success
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: sh[0xd618bc0], connected[1], ops[(nil)], ldap[0xd619300]
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
(Tue Jan 10 06:01:09 2012) [sssd[be[lab.eng.pnq.redhat.com]]] [delayed_online_authentication_callback] (5): Backend is online, starting delayed online authentication.


[root@ratchet ~]# ssh -l shanks $HOSTNAME
shanks.eng.pnq.redhat.com's password: 
Warning: Your password will expire in less than one hour.
Password expired. Change your password now.
WARNING: Your password has expired.
You must change your password now and login again!
Changing password for user shanks.
Current Password: 
New UNIX password: 
Retype new UNIX password: 
Warning: Your password will expire in less than one hour.
passwd: Authentication token manipulation error
Connection to ratchet.lab.eng.pnq.redhat.com closed.
[root@ratchet ~]# 

[root@ratchet ~]# ssh -l shanks $HOSTNAME
shanks.eng.pnq.redhat.com's password: 
Last login: Tue Jan 10 06:02:08 2012 from ratchet.lab.eng.pnq.redhat.com
-sh-3.2$ 


Server: ipa-server-2.1.3-9.el6.x86_64
Client: sssd-1.5.1-47.el5
Comment 4 errata-xmlrpc 2012-02-21 06:22:52 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2012-0164.html