Bug 1389709

Summary: Traceback seen in error_log when trustdomain-del is run
Product: Red Hat Enterprise Linux 7 Reporter: Sudhir Menon <sumenon>
Component: ipaAssignee: IPA Maintainers <ipa-maint>
Status: CLOSED ERRATA QA Contact: Sudhir Menon <sumenon>
Severity: unspecified Docs Contact:
Priority: medium    
Version: 7.3CC: abokovoy, ipa-qe, jcholast, mbabinsk, mkolaja, nsoman, pvoborni, rcritten
Target Milestone: rcKeywords: Regression, ZStream
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ipa-4.4.0-14.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1390673 (view as bug list) Environment:
Last Closed: 2017-08-01 09:42:02 UTC Type: Bug
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:    
Bug Blocks: 1390673    

Description Sudhir Menon 2016-10-28 09:43:04 UTC
Description of problem: Traceback seen in error_log when trustdomain-del is run.


Version-Release number of selected component (if applicable):
ipa-server-4.4.0-12.el7.x86_64

How reproducible:
Always


Steps to Reproduce:
1. Install IPA server. Ensure /etc/ipa/default.conf has 'debug = True' entry in global section
2. Ensure trust is established with AD server having a child domain.
3. Now try to delete the trust as below

[root@master ~]# ipa trustdomain-del pne.qe chd.pne.qe

Actual results:

1. The below message is displayed on the console.
[root@master ~]# ipa trustdomain-del pne.qe chd.pne.qe
ipa: ERROR: chd.pne.qe: trust not found

2. The httpd error_log file displays the below message.
[Fri Oct 28 15:04:12.038329 2016] [:error] [pid 24690] ipa: DEBUG: Destroyed connection context.ldap2_140675937010000
[Fri Oct 28 15:11:03.749083 2016] [:error] [pid 24689] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Fri Oct 28 15:11:03.749332 2016] [:error] [pid 24689] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Fri Oct 28 15:11:03.749963 2016] [:error] [pid 24689] ipa: DEBUG: found session cookie_id = a9765676c3fa652eb7f36248c39aecef
[Fri Oct 28 15:11:03.751150 2016] [:error] [pid 24689] ipa: DEBUG: found session data in cache with id=a9765676c3fa652eb7f36248c39aecef
[Fri Oct 28 15:11:03.751575 2016] [:error] [pid 24689] ipa: DEBUG: jsonserver_session.__call__: session_id=a9765676c3fa652eb7f36248c39aecef start_timestamp=2016-10-28T15:00:33 access_timestamp=2016-10-28T15:11:03 expiration_timestamp=2016-10-28T15:24:11
[Fri Oct 28 15:11:03.751688 2016] [:error] [pid 24689] ipa: DEBUG: storing ccache data into file "/var/run/ipa_memcached/krbcc_24689"
[Fri Oct 28 15:11:03.755197 2016] [:error] [pid 24689] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1477721962.75 expiration=1477648863.76 (2016-10-28T15:31:03)
[Fri Oct 28 15:11:03.818170 2016] [:error] [pid 24689] ipa: DEBUG: Created connection context.ldap2_140675937010000
[Fri Oct 28 15:11:03.818283 2016] [:error] [pid 24689] ipa: DEBUG: WSGI jsonserver.__call__:
[Fri Oct 28 15:11:03.818387 2016] [:error] [pid 24689] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Fri Oct 28 15:11:03.819726 2016] [:error] [pid 24689] ipa: DEBUG: raw: trust_del((u'pne.qe', u'chd.pne.qe'), version=u'2.213')
[Fri Oct 28 15:11:03.820214 2016] [:error] [pid 24689] ipa: DEBUG: trust_del((u'pne.qe', u'chd.pne.qe'), continue=False, version=u'2.213')
[Fri Oct 28 15:11:04.026405 2016] [:error] [pid 24689] ipa: DEBUG: WSGI wsgi_execute PublicError: Traceback (most recent call last):
[Fri Oct 28 15:11:04.026445 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 366, in wsgi_execute
[Fri Oct 28 15:11:04.026449 2016] [:error] [pid 24689]     result = command(*args, **options)
[Fri Oct 28 15:11:04.026451 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 449, in __call__
[Fri Oct 28 15:11:04.026454 2016] [:error] [pid 24689]     return self.__do_call(*args, **options)
[Fri Oct 28 15:11:04.026457 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 477, in __do_call
[Fri Oct 28 15:11:04.026459 2016] [:error] [pid 24689]     ret = self.run(*args, **options)
[Fri Oct 28 15:11:04.026462 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 799, in run
[Fri Oct 28 15:11:04.026464 2016] [:error] [pid 24689]     return self.execute(*args, **options)
[Fri Oct 28 15:11:04.026467 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py", line 1571, in execute
[Fri Oct 28 15:11:04.026469 2016] [:error] [pid 24689]     delete_entry(pkey)
[Fri Oct 28 15:11:04.026472 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py", line 1520, in delete_entry
[Fri Oct 28 15:11:04.026474 2016] [:error] [pid 24689]     dn = self.obj.get_dn(*nkeys, **options)
[Fri Oct 28 15:11:04.026477 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/trust.py", line 604, in get_dn
[Fri Oct 28 15:11:04.026479 2016] [:error] [pid 24689]     self.handle_not_found(keys[-1])
[Fri Oct 28 15:11:04.026482 2016] [:error] [pid 24689]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py", line 759, in handle_not_found
[Fri Oct 28 15:11:04.026484 2016] [:error] [pid 24689]     'pkey': pkey, 'oname': self.object_name,
[Fri Oct 28 15:11:04.026487 2016] [:error] [pid 24689] NotFound: chd.pne.qe: trust not found
[Fri Oct 28 15:11:04.026506 2016] [:error] [pid 24689] 
[Fri Oct 28 15:11:04.026696 2016] [:error] [pid 24689] ipa: INFO: [jsonserver_session] admin: trust_del/1((u'pne.qe', u'chd.pne.qe'), version=u'2.213'): NotFound
[Fri Oct 28 15:11:04.027650 2016] [:error] [pid 24689] ipa: DEBUG: reading ccache data from file "/var/run/ipa_memcached/krbcc_24689"
[Fri Oct 28 15:11:04.028026 2016] [:error] [pid 24689] ipa: DEBUG: store session: session_id=a9765676c3fa652eb7f36248c39aecef start_timestamp=2016-10-28T15:00:33 access_timestamp=2016-10-28T15:11:04 expiration_timestamp=2016-10-28T15:31:03
[Fri Oct 28 15:11:04.030589 2016] [:error] [pid 24689] ipa: DEBUG: Destroyed connection context.ldap2_140675937010000

Expected results:
The trustdomain-del command should work without any traceback.

Additional info:

Comment 1 Sudhir Menon 2016-10-28 09:44:18 UTC
[root@master ~]# ipa trustdomain-find
Realm name: pne.qe
  Domain name: chd.pne.qe
  Domain NetBIOS name: CHD
  Domain Security Identifier: S-1-5-21-955784371-1403174198-1768577397
  Domain enabled: True
 
  Domain name: pne.qe
  Domain NetBIOS name: PNE
  Domain Security Identifier: S-1-5-21-2078409739-4279301341-3068256061
  Domain enabled: True

Comment 4 Petr Vobornik 2016-10-31 16:44:37 UTC
Upstream ticket:
https://fedorahosted.org/freeipa/ticket/6445

Comment 10 Sudhir Menon 2017-05-15 09:48:58 UTC
Verified using below rpms on RHEL 7.4(Maipo)

ipa-server-4.5.0-11.el7.x86_64
389-ds-base-1.3.6.1-13.el7.x86_64
pki-ca-10.4.1-4.el7.noarch
sssd-1.15.2-29.el7.x86_64
krb5-server-1.15.1-8.el7.x86_64

[root@master ~]# ipa trustdomain-del pne.qe chd.pne.qe
ipa: DEBUG: importing all plugin modules in ipaclient.remote_plugins.schema$77a7b791...
ipa: DEBUG: importing plugin module ipaclient.remote_plugins.schema$77a7b791.plugins
ipa: DEBUG: importing all plugin modules in ipaclient.plugins...
ipa: DEBUG: importing plugin module ipaclient.plugins.automember
ipa: DEBUG: importing plugin module ipaclient.plugins.automount
ipa: DEBUG: importing plugin module ipaclient.plugins.ca
ipa: DEBUG: importing plugin module ipaclient.plugins.cert
ipa: DEBUG: importing plugin module ipaclient.plugins.certmap
ipa: DEBUG: importing plugin module ipaclient.plugins.certprofile
ipa: DEBUG: importing plugin module ipaclient.plugins.dns
ipa: DEBUG: importing plugin module ipaclient.plugins.hbacrule
ipa: DEBUG: importing plugin module ipaclient.plugins.hbactest
ipa: DEBUG: importing plugin module ipaclient.plugins.host
ipa: DEBUG: importing plugin module ipaclient.plugins.idrange
ipa: DEBUG: importing plugin module ipaclient.plugins.internal
ipa: DEBUG: importing plugin module ipaclient.plugins.location
ipa: DEBUG: importing plugin module ipaclient.plugins.migration
ipa: DEBUG: importing plugin module ipaclient.plugins.misc
ipa: DEBUG: importing plugin module ipaclient.plugins.otptoken
ipa: DEBUG: importing plugin module ipaclient.plugins.otptoken_yubikey
ipa: DEBUG: importing plugin module ipaclient.plugins.passwd
ipa: DEBUG: importing plugin module ipaclient.plugins.permission
ipa: DEBUG: importing plugin module ipaclient.plugins.rpcclient
ipa: DEBUG: importing plugin module ipaclient.plugins.server
ipa: DEBUG: importing plugin module ipaclient.plugins.service
ipa: DEBUG: importing plugin module ipaclient.plugins.sudorule
ipa: DEBUG: importing plugin module ipaclient.plugins.topology
ipa: DEBUG: importing plugin module ipaclient.plugins.trust
ipa: DEBUG: importing plugin module ipaclient.plugins.user
ipa: DEBUG: importing plugin module ipaclient.plugins.vault
ipa: DEBUG: found session_cookie in persistent storage for principal 'admin', cookie: 'ipa_session=MagBearerToken=GrpNz%2fWkeN1Nw0o90e3okeK48wHVGcG7HS9QCpMrpJ1AWzbqvDe5CZxLWwgZk1aiz6FFzkiSFdeCkcbpZ6BkD58wzM3CfeQHlqdj9mVuvPP7TipJ%2fSDdFtmFtXZ8yVj7PvEF%2fPGHuNJ3uYyJ4g7d%2fx13%2b8a8t%2fjvyAgB3g4irWY3eQI8%2fvVJdu3YWthzTY2g'
ipa: DEBUG: setting session_cookie into context 'ipa_session=MagBearerToken=GrpNz%2fWkeN1Nw0o90e3okeK48wHVGcG7HS9QCpMrpJ1AWzbqvDe5CZxLWwgZk1aiz6FFzkiSFdeCkcbpZ6BkD58wzM3CfeQHlqdj9mVuvPP7TipJ%2fSDdFtmFtXZ8yVj7PvEF%2fPGHuNJ3uYyJ4g7d%2fx13%2b8a8t%2fjvyAgB3g4irWY3eQI8%2fvVJdu3YWthzTY2g;'
ipa: INFO: trying https://master.testrelm.test/ipa/session/json
ipa: DEBUG: Created connection context.rpcclient_55395344
ipa: DEBUG: raw: trustdomain_del(u'pne.qe', (u'chd.pne.qe',), version=u'2.224')
ipa: DEBUG: trustdomain_del(u'pne.qe', (u'chd.pne.qe',), version=u'2.224')
ipa: INFO: Forwarding 'trustdomain_del/1' to json server 'https://master.testrelm.test/ipa/session/json'
ipa: DEBUG: New HTTP connection (master.testrelm.test)
ipa: DEBUG: received Set-Cookie (<type 'list'>)'['ipa_session=MagBearerToken=GrpNz%2fWkeN1Nw0o90e3okeK48wHVGcG7HS9QCpMrpJ1AWzbqvDe5CZxLWwgZk1aiz6FFzkiSFdeCkcbpZ6BkD58wzM3CfeQHlqdj9mVuvPP7TipJ%2fSDdFtmFtXZ8yVj7PvEF%2fPGHuNJ3uYyJ4g7d%2fx13%2b8a8t%2fjvyAgB3g4irWY3eQI8%2fvVJdu3YWthzTY2g&expiry=1494843214527469;Max-Age=1800;path=/ipa;httponly;secure;']'
ipa: DEBUG: storing cookie 'ipa_session=MagBearerToken=GrpNz%2fWkeN1Nw0o90e3okeK48wHVGcG7HS9QCpMrpJ1AWzbqvDe5CZxLWwgZk1aiz6FFzkiSFdeCkcbpZ6BkD58wzM3CfeQHlqdj9mVuvPP7TipJ%2fSDdFtmFtXZ8yVj7PvEF%2fPGHuNJ3uYyJ4g7d%2fx13%2b8a8t%2fjvyAgB3g4irWY3eQI8%2fvVJdu3YWthzTY2g;' for principal admin
ipa: DEBUG: Destroyed connection context.rpcclient_55395344
---------------------------------------------------------
Removed information about the trusted domain "chd.pne.qe"
---------------------------------------------------------

[root@master ~]# ipa trust-find pne.qe
---------------
1 trust matched
---------------
  Realm name: pne.qe
  Domain NetBIOS name: PNE
  Domain Security Identifier: S-1-5-21-2202318585-426110948-4011710778
  Trust type: Active Directory domain
  UPN suffixes: test.qa, pune.in
----------------------------
Number of entries returned 1
----------------------------
[root@master ~]# ipa trust-find chd.pne.qe
----------------
0 trusts matched
----------------
----------------------------
Number of entries returned 0
----------------------------

Comment 11 errata-xmlrpc 2017-08-01 09:42:02 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.

https://access.redhat.com/errata/RHBA-2017:2304