ipa-replica-install fails in test scenario with 3 replicas returning:
2017-03-30T12:18:09Z DEBUG The ipa-replica-install command failed, exception: HTTPError: 406 Client Error: Failed to validate message: Incorrect number of results (0) searching forpublic key for host/replica1.ipa.test@IPA.TEST for url: https://master.ipa.test/ipa/keys/ca/caSigningCert%20cert-pki-ca?type=kem&value=eyJhbGciOiJSU0EtT0FFUCIsImVuYyI6IkEyNTZDQkMtSFM1MTIiLCJraWQiOm51bGx9.st5sUjSqgZ0YUXqSrRDB0jBMnT4tZDiau13OW1Tazfmz8vQKL5ngB41qr69CN1gHy3eiWqmJPK_f8MJsBcydxw61mifpoAVS9BvPm0-OTXppc7ihrwsnAso3lYL5KU4zsNUvZw3rDLhc22gLZyYqKzLDhH-EglRjjHxtfJ5dimPjEU9HXMv310gZt-D57_K0VWZt7lv-Vkb_3fppkNeLrm7wK82RcgsE680BFGdAq6DNiG1zrXcZVV0oR1alPpa7EJHey0HaqvGIX1dzYrCD2_-z2kO-20IFC1fePpItM6fynVUFJMk_u8aRNSB3ea2WMyetJNXrbB_rRKiCEjqGEg.b7W6VA-gFQ4pPJd06kKY1w.-41PkK511sCnRZ7w_StI9iVhfc5YB4grxndI-YkbwIivJ2ZZtHDhDlMtn-FjtDITMmECUBbrtopjvWcz688fNs93JVQ4W2sxmR96ETOQolnTqN693Xot3pZt0UZMPsbdSrIR1nQRiF03TfuJeGBjs1HlnZ36VhSpP1t8u_pagTLEGoRYrRPu9jMH6-T7C74_a1aEEL5gherssIWNNEchVPGlf16U-iCrBRdu2HRijzXMdIEmB-uGiTBjMtO8WhGOXq8hKdzGfpYi9d8E67qOAC6TOnoYVpe7eyPyhtQgAiPXK_m-T8Z8Y8v3LBEYp5ezFY2eZ4KXqyneNwsw1PsDHC7Eb5x-5IJOJBarb_L8d706kjPwdFSu9L0X47w9TTAK7QxPDCJclEl-Uft2GvZrgHTZtkaF3SOOmMh-Pjv5fq4M8-_gnBTP7ClyOUJufLXvPrdD20lq0DxARmmwith11d3QJ5Lt1Bj7HuCq9-29FuQxtWpPIIRA9IVIU3pfjtdzNJwCoP0H7SyewM4-q_WcwLR92r7qSF-94gd-f9NKnNGYiecOEy1gkdoM4DIOUo2uYAtbRyrrJMrKES_s2FYRnXUBsgKRnTBjZ-4sffjd4C1X72__AxtI2_ZHjzkW54fn5UPv5MumuakLNYaCG1yGqQ.HIaJTgkRi2Ii6ZKOFidJP8ZM3IQFgjZMZZ_Xnoz8gZ4 2017-03-30T12:18:09Z ERROR 406 Client Error: Failed to validate message: Incorrect number of results (0) searching forpublic key for host/replica1.ipa.test@IPA.TEST for url: https://master.ipa.test/ipa/keys/ca/caSigningCert%20cert-pki-ca?type=kem&value=eyJhbGciOiJSU0EtT0FFUCIsImVuYyI6IkEyNTZDQkMtSFM1MTIiLCJraWQiOm51bGx9.st5sUjSqgZ0YUXqSrRDB0jBMnT4tZDiau13OW1Tazfmz8vQKL5ngB41qr69CN1gHy3eiWqmJPK_f8MJsBcydxw61mifpoAVS9BvPm0-OTXppc7ihrwsnAso3lYL5KU4zsNUvZw3rDLhc22gLZyYqKzLDhH-EglRjjHxtfJ5dimPjEU9HXMv310gZt-D57_K0VWZt7lv-Vkb_3fppkNeLrm7wK82RcgsE680BFGdAq6DNiG1zrXcZVV0oR1alPpa7EJHey0HaqvGIX1dzYrCD2_-z2kO-20IFC1fePpItM6fynVUFJMk_u8aRNSB3ea2WMyetJNXrbB_rRKiCEjqGEg.b7W6VA-gFQ4pPJd06kKY1w.-41PkK511sCnRZ7w_StI9iVhfc5YB4grxndI-YkbwIivJ2ZZtHDhDlMtn-FjtDITMmECUBbrtopjvWcz688fNs93JVQ4W2sxmR96ETOQolnTqN693Xot3pZt0UZMPsbdSrIR1nQRiF03TfuJeGBjs1HlnZ36VhSpP1t8u_pagTLEGoRYrRPu9jMH6-T7C74_a1aEEL5gherssIWNNEchVPGlf16U-iCrBRdu2HRijzXMdIEmB-uGiTBjMtO8WhGOXq8hKdzGfpYi9d8E67qOAC6TOnoYVpe7eyPyhtQgAiPXK_m-T8Z8Y8v3LBEYp5ezFY2eZ4KXqyneNwsw1PsDHC7Eb5x-5IJOJBarb_L8d706kjPwdFSu9L0X47w9TTAK7QxPDCJclEl-Uft2GvZrgHTZtkaF3SOOmMh-Pjv5fq4M8-_gnBTP7ClyOUJufLXvPrdD20lq0DxARmmwith11d3QJ5Lt1Bj7HuCq9-29FuQxtWpPIIRA9IVIU3pfjtdzNJwCoP0H7SyewM4-q_WcwLR92r7qSF-94gd-f9NKnNGYiecOEy1gkdoM4DIOUo2uYAtbRyrrJMrKES_s2FYRnXUBsgKRnTBjZ-4sffjd4C1X72__AxtI2_ZHjzkW54fn5UPv5MumuakLNYaCG1yGqQ.HIaJTgkRi2Ii6ZKOFidJP8ZM3IQFgjZMZZ_Xnoz8gZ4
However in LDAP everything looks fine - 2 entries * 4 machines + dogtag container. Consulted with "cheimes" and looks like a race condition.
[root@replica1 ~]# rpm -qa | egrep "custodia|freeipa" freeipa-server-common-4.5.90.dev201703290851+git67e5244-0.fc25.noarch freeipa-server-trust-ad-4.5.90.dev201703290851+git67e5244-0.fc25.x86_64 freeipa-client-common-4.5.90.dev201703290851+git67e5244-0.fc25.noarch freeipa-common-4.5.90.dev201703290851+git67e5244-0.fc25.noarch custodia-0.3.1-1.fc25.noarch freeipa-server-dns-4.5.90.dev201703290851+git67e5244-0.fc25.noarch freeipa-python-compat-4.5.90.dev201703290851+git67e5244-0.fc25.noarch freeipa-debuginfo-4.5.90.dev201703290851+git67e5244-0.fc25.x86_64 freeipa-client-4.5.90.dev201703290851+git67e5244-0.fc25.x86_64 python3-custodia-0.3.1-1.fc25.noarch freeipa-server-4.5.90.dev201703290851+git67e5244-0.fc25.x86_64 python2-custodia-0.3.1-1.fc25.noarch
Output of:
ldapsearch -H ldapi://%2fvar%2frun%2fslapd-IPA-TEST.socket -Y EXTERNAL -s one -b cn=custodia,cn=ipa,cn=etc,dc=ipa,dc=test"
<img alt="ldap" src="/freeipa/issue/raw/files/482911fc921fb0db41ab251e6f73e3d5a1c81cbd6296cdf9626521524bac2e99-ldap" />
Failing in this section of "ipa-replica-install":
[ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] Configuring ipa-custodia [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] [1/4]: Generating ipa-custodia config file [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] [2/4]: Generating ipa-custodia keys [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] [3/4]: starting ipa-custodia [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] [4/4]: configuring ipa-custodia to start on boot [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] Done configuring ipa-custodia. [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] ipa.ipapython.install.cli.install_tool(CompatServerReplicaInstall): ERROR 406 Client Error: Failed to validate message: Incorrect number of results (0) searching forpublic key for host/replica1.ipa.test@IPA.TEST for url: https://master.ipa.test/ipa/keys/ca/caSigningCert%20cert-pki-ca?type=kem&value=eyJhbGciOiJSU0EtT0FFUCIsImVuYyI6IkEyNTZDQkMtSFM1MTIiLCJraWQiOm51bGx9.st5sUjSqgZ0YUXqSrRDB0jBMnT4tZDiau13OW1Tazfmz8vQKL5ngB41qr69CN1gHy3eiWqmJPK_f8MJsBcydxw61mifpoAVS9BvPm0-OTXppc7ihrwsnAso3lYL5KU4zsNUvZw3rDLhc22gLZyYqKzLDhH-EglRjjHxtfJ5dimPjEU9HXMv310gZt-D57_K0VWZt7lv-Vkb_3fppkNeLrm7wK82RcgsE680BFGdAq6DNiG1zrXcZVV0oR1alPpa7EJHey0HaqvGIX1dzYrCD2_-z2kO-20IFC1fePpItM6fynVUFJMk_u8aRNSB3ea2WMyetJNXrbB_rRKiCEjqGEg.b7W6VA-gFQ4pPJd06kKY1w.-41PkK511sCnRZ7w_StI9iVhfc5YB4grxndI-YkbwIivJ2ZZtHDhDlMtn-FjtDITMmECUBbrtopjvWcz688fNs93JVQ4W2sxmR96ETOQolnTqN693Xot3pZt0UZMPsbdSrIR1nQRiF03TfuJeGBjs1HlnZ36VhSpP1t8u_pagTLEGoRYrRPu9jMH6-T7C74_a1aEEL5gherssIWNNEchVPGlf16U-iCrBRdu2HRijzXMdIEmB-uGiTBjMtO8WhGOXq8hKdzGfpYi9d8E67qOAC6TOnoYVpe7eyPyhtQgAiPXK_m-T8Z8Y8v3LBEYp5ezFY2eZ4KXqyneNwsw1PsDHC7Eb5x-5IJOJBarb_L8d706kjPwdFSu9L0X47w9TTAK7QxPDCJclEl-Uft2GvZrgHTZtkaF3SOOmMh-Pjv5fq4M8-_gnBTP7ClyOUJufLXvPrdD20lq0DxARmmwith11d3QJ5Lt1Bj7HuCq9-29FuQxtWpPIIRA9IVIU3pfjtdzNJwCoP0H7SyewM4-q_WcwLR92r7qSF-94gd-f9NKnNGYiecOEy1gkdoM4DIOUo2uYAtbRyrrJMrKES_s2FYRnXUBsgKRnTBjZ-4sffjd4C1X72__AxtI2_ZHjzkW54fn5UPv5MumuakLNYaCG1yGqQ.HIaJTgkRi2Ii6ZKOFidJP8ZM3IQFgjZMZZ_Xnoz8gZ4 [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] ipa.ipapython.install.cli.install_tool(CompatServerReplicaInstall): ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] Your system may be partly configured. [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] Run /usr/sbin/ipa-server-install --uninstall to clean up. [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] [ipa.ipatests.pytest_plugins.integration.host.Host.replica1.cmd21] Exit code: 1
In addition: replica1 connects to replica3 (replicas without CA)
@mreznik was able to reproduce the problem again. Here is another log and ldap search:
<img alt="log" src="/freeipa/issue/raw/files/893b2e31641f1e81ffe57a88ce716742a968cbf32adb217f94cf955a443bd2f4-log" />
The key request failed because ipa-custodia on vm-202 (master) did no see the public keys of vm-058-090 in LDAP. I see two options to work around the race condition:
1) Add a blocking wait to ipa-custodia and use something similar to ipaserver.install.replication.wait_for_entry to wait until the host entries have been replicated. 2) Turn the missing key error into a different HTTP error like 412 Precondition Failed or 428 Precondition Required. Then the client can handle these error codes in a special way and retry the request a couple of times with some delay.
ipaserver.install.replication.wait_for_entry
412 Precondition Failed
428 Precondition Required
Solution 1 is simpler and backwards compatible, but also a hack. We also have to ensure that replica deletion removes these keys. Otherwise we might run into more trouble.
Solution 2 is a bit harder to implement.
Metadata Update from @pvoborni: - Issue priority set to: blocker - Issue set to the milestone: FreeIPA 4.5.1 - Issue tagged with: bug
Metadata Update from @pvoborni: - Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/679
Metadata Update from @pvoborni: - Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1438833
Issue linked to bug 1438833
Metadata Update from @pvoborni: - Issue assigned to simo
ipa-4-5:
master:
Metadata Update from @tkrizek: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
The issue reappeared yesterday on Jenkins in "TestLineTopologyWithCA--test_line_topology_with_ca (and without)"
File "/usr/lib/python2.7/site-packages/ipaserver/secrets/client.py", line 24, in _server_keys sk = JWK(**json_decode(self.ikk.find_key(principal, KEY_USAGE_SIG))) File "/usr/lib/python2.7/site-packages/ipaserver/secrets/kem.py", line 201, in find_key return conn.get_key(usage, kid) File "/usr/lib/python2.7/site-packages/ipaserver/secrets/kem.py", line 76, in get_key "public key for %s" % (len(r), principal)) 2017-06-06T06:20:10Z DEBUG The ipa-replica-install command failed, exception: ValueError: Incorrect number of results (0) searching for public key for host/vm-058-057.abc.idm.lab.ipa.test@DOM-058-200.ABC.IDM.LAB.ipa.test 2017-06-06T06:20:10Z ERROR Incorrect number of results (0) searching for public key for host/vm-058-057.abc.idm.lab.ipa.test@DOM-058-200.ABC.IDM.LAB.ipa.test 2017-06-06T06:20:10Z ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information
vm-058-200 - master vm-058-200 <- vm-058-057 vm-058-057 <- vm-058-171
Attaching ipareplica-install logs from "vm-058-171"
<img alt="ipareplica-install_20170607" src="/freeipa/issue/raw/05334e36ab71123d029fe287decf8f7928b1dc2a6ec6a85549ea3e6f67a852fb-ipareplica-install_20170607" />
Metadata Update from @mreznik: - Issue status updated to: Open (was: Closed)
The fix added __wait_keys method for obtaining CA and KRA keys. But this recent failure and probably the one which @stlaz saw during review is in import_dm_password method in sk = JWK(**json_decode(self.ikk.find_key(principal, KEY_USAGE_SIG))) and it seems to me that there is no wait in this part of code. I don't know this code so not sure if wait should be there but it should be investigated.
__wait_keys
import_dm_password
sk = JWK(**json_decode(self.ikk.find_key(principal, KEY_USAGE_SIG)))
@stlaz , @simo what do you think?
Adding also part where it is failing in the test. Full traceback in "ipareplica-install" file.
[2017-06-06T06:18:59Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: [5/9]: starting directory server [2017-06-06T06:19:00Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: [6/9]: upgrading server [2017-06-06T06:20:07Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: [7/9]: stopping directory server [2017-06-06T06:20:08Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: [8/9]: restoring configuration [2017-06-06T06:20:08Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: [9/9]: starting directory server [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: Done. [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: Restarting the KDC [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: Your system may be partly configured. [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: Run /usr/sbin/ipa-server-install --uninstall to clean up. [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: ipa.ipapython.install.cli.install_tool(CompatServerReplicaInstall): ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information ipa: ERROR: Exit code: 1 [2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <ERROR>: Exit code: 1 ______________ TestLineTopologyWithCA.test_line_topology_with_ca _______________ self = <ipatests.test_integration.test_replication_layouts.TestLineTopologyWithCA object at 0x7fd51c668310> def test_line_topology_with_ca(self): tasks.install_topo('line', self.master, self.replicas, [], > setup_replica_cas=True) test_integration/test_replication_layouts.py:51: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ pytest_plugins/integration/tasks.py:1030: in install_topo setup_kra=setup_replica_kra pytest_plugins/integration/tasks.py:388: in install_replica install_client(master, replica) pytest_plugins/integration/tasks.py:420: in install_client + list(extra_args)) ../pytest_multihost/host.py:251: in run_command command.wait(raiseonerr=raiseonerr) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <pytest_multihost.transport.SSHCommand object at 0x7fd51c668650> raiseonerr = True def wait(self, raiseonerr=True): """Wait for the remote process to exit Raises an excption if the exit code is not 0, unless raiseonerr is true. """ if self._done: return self.returncode self._end_process() self._done = True if raiseonerr and self.returncode: self.log.error('Exit code: %s', self.returncode) > raise subprocess.CalledProcessError(self.returncode, self.argv) E CalledProcessError: Command '['ipa-client-install', '-U', '--domain', 'dom-058-200.abc.idm.lab.ipa.test.com', '--realm', 'DOM-058-200.ABC.IDM.LAB.ipa.test.COM', '-p', 'admin', '-w', 'Secret123', '--server', 'vm-058-057.abc.idm.lab.ipa.test.com']' returned non-zero exit status 3 ../pytest_multihost/transport.py:159: CalledProcessError ---------------------------- Captured stdout setup ----------------------------- <ipatests.pytest_plugins.integration.config.Config object at 0x7fd51c782dd0> ---------------------------- Captured stderr setup ----------------------------- [2017-06-06T06:21:17Z ipa.ipatests.test_integration.base.IntegrationTest] <INFO>: Preparing host vm-058-200.abc.idm.lab.ipa.test.com [2017-06-06T06:21:17Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-200.ParamikoTransport] <DEBUG>: Authenticating with private RSA key using user root [2017-06-06T06:21:18Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-200.ParamikoTransport] <INFO>: RUN ['true'] [2017-06-06T06:21:18Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-200.cmd1] <DEBUG>: RUN ['true'] [2017-06-06T06:21:18Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-200.cmd1] <DEBUG>: -bash: line 1: cd: /root/ipatests: No such file or directory [2017-06-06T06:21:18Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-200.cmd1] <DEBUG>: Exit code: 0
Not sure how this is related? This seem to be failing on the ipa-client-install step? What am I reading wrong ?
On 11th line it is saying:
[2017-06-06T06:20:10Z ipa.ipatests.pytest_plugins.integration.host.Host.vm-058-171.cmd21] <DEBUG>: ipa.ipapython.install.cli.install_tool(CompatServerReplicaInstall): ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information
This is the output I see from the test logs. Sorry If it is not informative enough. I can provide link for the Jenkins job out of this ticket or try to reproduce locally but this may take some time.
we need the ipareplica-install file to know what failed
I mean ipareplica-install.log
ipareplica-install_20170607 (ipareplica-install.log) file was attached right after reopening this case.
Metadata Update from @pvomacka: - Issue set to the milestone: FreeIPA 4.5.3 (was: FreeIPA 4.5.1)
Metadata Update from @pvomacka: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Log in to comment on this ticket.