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 - 4.6.0 server deployment fails due to issue contacting CA(?)
Summary: 4.6.0 server deployment fails due to issue contacting CA(?)
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: 389-ds-base
Version: 27
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Rich Megginson
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: F27BetaBlocker
TreeView+ depends on / blocked
 
Reported: 2017-09-05 04:29 UTC by Adam Williamson
Modified: 2017-09-09 04:10 UTC (History)
19 users (show)

Fixed In Version: 389-ds-base-1.3.7.3-1.fc27
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-09-09 04:10:57 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
tarball containing all of /var/log from the failed test (1.82 MB, application/octet-stream)
2017-09-05 04:31 UTC, Adam Williamson
no flags Details

Description Adam Williamson 2017-09-05 04:29:12 UTC
The 4.6.0 update just arrived for Fedora 27:

https://bodhi.fedoraproject.org/updates/FEDORA-2017-a79e85e4d3

dgilmore created it for us after fixing that issue with the noarch package diff check. openQA tested it, but it failed once more:

https://openqa.stg.fedoraproject.org/tests/154377

(that's the test on staging, which is currently hacked up to run with SELinux in permissive mode, to avoid AVCs failing things). The ultimate error in ipaserver-install.log is:

2017-09-05T01:32:36Z DEBUG The ipa-server-install command failed, exception: RuntimeError: CA did not start in 300.0s
2017-09-05T01:32:36Z ERROR CA did not start in 300.0s

but I'm not sure specifically why reaching the CA server failed. I'll attach the tarball containing the whole of /var/log .

Proposing as a Beta blocker, again as this breaks deployment of a release-blocking role (domain controller).

Note the update contains only FreeIPA, we did not know of any other packages that have to be updated in sync - if the FreeIPA update must be tested along with bumps to any other packages, please let us know so we can edit the appropriate builds into the update. Thanks!

Comment 1 Adam Williamson 2017-09-05 04:31:40 UTC
Created attachment 1322050 [details]
tarball containing all of /var/log from the failed test

Comment 2 Standa Laznicka 2017-09-05 08:19:55 UTC
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.

Comment 3 Standa Laznicka 2017-09-05 08:50:45 UTC
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?

Comment 4 Standa Laznicka 2017-09-05 10:08:12 UTC
Turns out we need 389-ds-base-1.3.7.3-1 because there was a bug in previous versions...

Comment 5 Tomas Krizek 2017-09-05 10:19:42 UTC
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.

Comment 6 Tomas Krizek 2017-09-05 13:25:38 UTC
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/

Comment 7 Adam Williamson 2017-09-05 15:51:42 UTC
Note, I don't currently test replication in the openQA tests as it wasn't included in the Fedora release criteria.

Comment 8 Adam Williamson 2017-09-05 15:55:29 UTC
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.

Comment 9 Fedora Update System 2017-09-05 16:42:34 UTC
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

Comment 10 Fedora Update System 2017-09-07 14:30:01 UTC
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

Comment 11 Fedora Update System 2017-09-09 04:10:57 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.