Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1488295
Summary: | 4.6.0 server deployment fails due to issue contacting CA(?) | ||||||
---|---|---|---|---|---|---|---|
Product: | [Fedora] Fedora | Reporter: | Adam Williamson <awilliam> | ||||
Component: | 389-ds-base | Assignee: | Rich Megginson <rmeggins> | ||||
Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||
Severity: | high | Docs Contact: | |||||
Priority: | unspecified | ||||||
Version: | 27 | CC: | abokovoy, cglombek, edewata, gparente, ipa-maint, jcholast, jhrozek, mkosek, mreynolds, nhosoi, nkinder, pvoborni, rcritten, rmeggins, robatino, slaznick, ssorce, tkrizek, tomek | ||||
Target Milestone: | --- | ||||||
Target Release: | --- | ||||||
Hardware: | x86_64 | ||||||
OS: | Linux | ||||||
Whiteboard: | |||||||
Fixed In Version: | 389-ds-base-1.3.7.3-1.fc27 | Doc Type: | If docs needed, set a value | ||||
Doc Text: | Story Points: | --- | |||||
Clone Of: | Environment: | ||||||
Last Closed: | 2017-09-09 04:10:57 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: | 1396702 | ||||||
Attachments: |
|
Description
Adam Williamson
2017-09-05 04:29:12 UTC
Created attachment 1322050 [details]
tarball containing all of /var/log from the failed test
Adam, thank you guys for so much hard effort you're putting into this. I identified the error. In /var/log/pki/pki-tomcat/ca/system you can see the following: """ 0.authorityMonitor - [04/Sep/2017:21:27:24 EDT] [8] [3] In Ldap (bound) connection pool to host ipa001.domain.local port 389, Cannot connect to LDAP server. Error: netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (Connection refused) (-1) """ Looking into /var/log/dirsrv/slapd-DOMAIN-LOCAL/access, one of the last records: """ [04/Sep/2017:21:27:40.227213991 -0400] conn=3 fd=64 slot=64 SSL connection from 10.0.2.100 to 10.0.2.100 [04/Sep/2017:21:27:40.234206049 -0400] conn=3 TLS1.2 128-bit AES [04/Sep/2017:21:27:40.248667005 -0400] conn=3 op=0 BIND dn="" method=sasl version=3 mech=EXTERNAL [04/Sep/2017:21:27:40.249908457 -0400] conn=3 op=0 RESULT err=48 tag=97 nentries=0 etime=0.0021159491 """ This happens after TLS was enabled for the DS: """ 2017-09-05T01:27:01Z DEBUG [1/3]: configuring TLS for DS instance 2017-09-05T01:27:16Z DEBUG [2/3]: adding CA certificate entry 2017-09-05T01:27:16Z DEBUG [3/3]: restarting directory server """ However, there's a few other steps that may taint this installation: """ 2017-09-05T01:27:25Z INFO [Set up lightweight CA key retrieval] 2017-09-05T01:27:25Z INFO Creating principal 2017-09-05T01:27:25Z DEBUG Starting external process 2017-09-05T01:27:25Z DEBUG args=kadmin.local -q addprinc -randkey dogtag/ipa001.domain.local -x ipa-setup-override-restrictions 2017-09-05T01:27:25Z DEBUG Process finished, return code=0 2017-09-05T01:27:25Z DEBUG stdout=Authenticating as principal root/admin with password. Principal "dogtag/ipa001.domain.local" created. 2017-09-05T01:27:25Z DEBUG stderr=WARNING: no policy specified for dogtag/ipa001.domain.local; defaulting to no policy 2017-09-05T01:27:25Z DEBUG flushing ldapi://%2fvar%2frun%2fslapd-DOMAIN-LOCAL.socket from SchemaCache 2017-09-05T01:27:25Z DEBUG retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-DOMAIN-LOCAL.socket conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7f55dbe1f470> 2017-09-05T01:27:26Z INFO Retrieving keytab 2017-09-05T01:27:26Z DEBUG Starting external process 2017-09-05T01:27:26Z DEBUG args=kadmin.local -q ktadd -k /etc/pki/pki-tomcat/dogtag.keytab dogtag/ipa001.domain.local -x ipa-setup-override-restrictions 2017-09-05T01:27:26Z DEBUG Process finished, return code=0 2017-09-05T01:27:26Z DEBUG stdout=Authenticating as principal root/admin with password. Entry for principal dogtag/ipa001.domain.local with kvno 2, encryption type aes256-cts-hmac-sha1-96 added to keytab WRFILE:/etc/pki/pki-tomcat/dogtag.keytab. Entry for principal dogtag/ipa001.domain.local with kvno 2, encryption type aes128-cts-hmac-sha1-96 added to keytab WRFILE:/etc/pki/pki-tomcat/dogtag.keytab. Entry for principal dogtag/ipa001.domain.local with kvno 2, encryption type des3-cbc-sha1 added to keytab WRFILE:/etc/pki/pki-tomcat/dogtag.keytab. Entry for principal dogtag/ipa001.domain.local with kvno 2, encryption type arcfour-hmac added to keytab WRFILE:/etc/pki/pki-tomcat/dogtag.keytab. Entry for principal dogtag/ipa001.domain.local with kvno 2, encryption type camellia128-cts-cmac added to keytab WRFILE:/etc/pki/pki-tomcat/dogtag.keytab. Entry for principal dogtag/ipa001.domain.local with kvno 2, encryption type camellia256-cts-cmac added to keytab WRFILE:/etc/pki/pki-tomcat/dogtag.keytab. 2017-09-05T01:27:26Z DEBUG stderr= 2017-09-05T01:27:26Z INFO Creating Custodia keys 2017-09-05T01:27:26Z DEBUG Created connection context.ldap2_140006717992296 2017-09-05T01:27:26Z DEBUG flushing ldapi://%2fvar%2frun%2fslapd-DOMAIN-LOCAL.socket from SchemaCache 2017-09-05T01:27:26Z DEBUG retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-DOMAIN-LOCAL.socket conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7f55dab12c50> 2017-09-05T01:27:26Z DEBUG Destroyed connection context.ldap2_140006717992296 2017-09-05T01:27:26Z DEBUG Created connection context.ldap2_140006717992016 2017-09-05T01:27:26Z DEBUG flushing ldapi://%2fvar%2frun%2fslapd-DOMAIN-LOCAL.socket from SchemaCache 2017-09-05T01:27:26Z DEBUG retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-DOMAIN-LOCAL.socket conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7f55dab13780> 2017-09-05T01:27:26Z DEBUG Destroyed connection context.ldap2_140006717992016 2017-09-05T01:27:27Z INFO Configuring key retriever 2017-09-05T01:27:27Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state' 2017-09-05T01:27:27Z DEBUG Saving StateFile to '/var/lib/ipa/sysupgrade/sysupgrade.state' 2017-09-05T01:27:27Z DEBUG Destroyed connection context.ldap2_140006773575240 2017-09-05T01:27:27Z DEBUG Starting external process 2017-09-05T01:27:27Z DEBUG args=/bin/systemctl restart dirsrv 2017-09-05T01:27:33Z DEBUG Process finished, return code=0 2017-09-05T01:27:33Z DEBUG stdout= 2017-09-05T01:27:33Z DEBUG stderr= 2017-09-05T01:27:33Z DEBUG Created connection context.ldap2_140006773575240 2017-09-05T01:27:33Z DEBUG Starting external process 2017-09-05T01:27:33Z DEBUG args=/bin/systemctl start pki-tomcatd 2017-09-05T01:27:33Z DEBUG Process finished, return code=0 2017-09-05T01:27:33Z DEBUG stdout= 2017-09-05T01:27:33Z DEBUG stderr= 2017-09-05T01:27:33Z DEBUG Starting external process 2017-09-05T01:27:33Z DEBUG args=/bin/systemctl is-active pki-tomcatd 2017-09-05T01:27:33Z DEBUG Process finished, return code=0 2017-09-05T01:27:33Z DEBUG stdout=active """ Then during the pki-tomcat restart, it obviously returns 500s when trying to access it via HTTP REST as it can't access the DS. I'll try to discuss this with our DS guys right away to find the solution. Btw: this was working like a month ago. Thanks to German Parente who pointed out to me that the DS connecting to 389 is weird. The installation actually fails after the last connection, which is agains port 636. The previous connections to LDAP 389 (before TLS was set up) fail as well, though. I don't think this should happen. It might be that Dogtag is unable to connect to the LDAP server the whole time? Turns out we need 389-ds-base-1.3.7.3-1 because there was a bug in previous versions... I can confirm this bug is resolved with 389-ds-base-1.3.7.3-1 Moving to 389-ds-base component, so the new build can be submitted to bodhi and pushed. It seems the CA_UNREACHABLE issue is now happening on replica with the new 389-ds-base version. Our CI has caught the issue when I attempted to bump the 389-ds-base version in our master branch: https://github.com/freeipa/freeipa/pull/1041 Please note that our PR CI uses Fedora 25 and our COPR repo, so the environment is slightly different. However, I expect we'll see this error in F27 as well. Logs from failed replica installation: https://fedorapeople.org/groups/freeipa/prci/jobs/8ffbfa8e-9238-11e7-9c4f-fa163e3a3a8c/test_integration-test_simple_replication.py-TestSimpleReplication--test_user_replication_to_replica/replica1.ipa.test/var/log/ Note, I don't currently test replication in the openQA tests as it wasn't included in the Fedora release criteria. Thanks, folks. I've edited the update to include 389-ds-base-1.3.7.3-1.fc27; openQA tests are running again, we'll see how they go this time. 389-ds-base-1.3.7.3-1.fc27 freeipa-4.6.0-1.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2017-a79e85e4d3 389-ds-base-1.3.7.3-1.fc27, freeipa-4.6.0-2.fc27, python-pyldap-2.4.37-2.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-a79e85e4d3 389-ds-base-1.3.7.3-1.fc27, freeipa-4.6.0-2.fc27, python-pyldap-2.4.37-2.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report. |