#9229 Random failure in ipa-replica-install while retrieving HTTP keytab
Opened 2 years ago by frenaud. Modified a year ago

Description

The nightly test test_installation_TestInstallWithCA_KRA_DNS1 detected a random issue during a replica installation: PR #1981, with logs and report.

The test is adding a replica with CA, and ipa-replica-install randomly fails in the step retrieving the HTTP keytab:

RUN ['ipa-replica-install', '--admin-password', 'Secret.123', '--password', 'Secret.123', '-U', '--setup-ca', '--ip-address', '192.168.122.142', '--realm', 'IPA.TEST', '--domain', 'ipa.test', '--dirsrv-config-file', '/ipatests/ipatests_dse.ldif']
Lookup failed: Preferred host replica2.ipa.test does not provide DNS.
Reverse DNS resolution of address 192.168.122.155 (master.ipa.test) failed. Clients may not function properly. Please check your DNS setup. (Note that this check queries IPA DNS directly and ignores /etc/hosts.)
IPA client is already configured on this system, ignoring the --domain, --server, --realm, --hostname, --password and --keytab options.
Run connection check to master
Connection check OK
Disabled p11-kit-proxy
Configuring directory server (dirsrv). Estimated time: 30 seconds
  [1/42]: creating directory server instance
...
Configuring directory server (dirsrv)
  [1/3]: configuring TLS for DS instance
  [2/3]: importing CA certificates from LDAP
  [3/3]: restarting directory server
Done configuring directory server (dirsrv).
Configuring the web interface (httpd)
  [1/22]: stopping httpd
  [2/22]: backing up ssl.conf
  [3/22]: disabling nss.conf
  [4/22]: configuring mod_ssl certificate paths
  [5/22]: setting mod_ssl protocol list
  [6/22]: configuring mod_ssl log directory
  [7/22]: disabling mod_ssl OCSP
  [8/22]: adding URL rewriting rules
  [9/22]: configuring httpd
  [10/22]: setting up httpd keytab
  [error] CalledProcessError: CalledProcessError(Command ['/usr/sbin/ipa-getkeytab', '-k', '/var/lib/ipa/gssproxy/http.keytab', '-p', 'HTTP/replica2.ipa.test@IPA.TEST', '-H', 'ldapi://%2Frun%2Fslapd-IPA-TEST.socket', '-Y', 'EXTERNAL'] returned non-zero exit status 9: 'Failed to parse result: Internal error while encrypting keys\n\nRetrying with pre-4.0 keytab retrieval method...\nFailed to parse result: Internal error.\n\nFailed to get keytab!\nFailed to get keytab\n')
CalledProcessError(Command ['/usr/sbin/ipa-getkeytab', '-k', '/var/lib/ipa/gssproxy/http.keytab', '-p', 'HTTP/replica2.ipa.test@IPA.TEST', '-H', 'ldapi://%2Frun%2Fslapd-IPA-TEST.socket', '-Y', 'EXTERNAL'] returned non-zero exit status 9: 'Failed to parse result: Internal error while encrypting keys\n\nRetrying with pre-4.0 keytab retrieval method...\nFailed to parse result: Internal error.\n\nFailed to get keytab!\nFailed to get keytab\n')
The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information
Your system may be partly configured.
Run /usr/sbin/ipa-server-install --uninstall to clean up.

Exit code: 1

Initial analysis

ipa-replica-install internally calls ipa-getkeytab in order to retrieve HTTP keytab (ipa-replica-install.log):

2022-08-25T01:22:26Z DEBUG Starting external process
2022-08-25T01:22:26Z DEBUG args=['/usr/sbin/ipa-getkeytab', '-k', '/var/lib/ipa/gssproxy/http.keytab', '-p', 'HTTP/replica2.ipa.test@IPA.TEST', '-H', 'ldapi://%2Frun%2Fslapd-IPA-TEST.socket', '-Y', 'EXTERNAL']
2022-08-25T01:22:26Z DEBUG Process finished, return code=9
2022-08-25T01:22:26Z DEBUG stdout=
2022-08-25T01:22:26Z DEBUG stderr=Failed to parse result: Internal error while encrypting keys

Retrying with pre-4.0 keytab retrieval method...
Failed to parse result: Internal error.

Failed to get keytab!
Failed to get keytab

2022-08-25T01:22:26Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.10/site-packages/ipaserver/install/service.py", line 686, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.10/site-packages/ipaserver/install/service.py", line 672, in run_step
    method()
  File "/usr/lib/python3.10/site-packages/ipaserver/install/httpinstance.py", line 625, in request_service_keytab
    super(HTTPInstance, self).request_service_keytab()
  File "/usr/lib/python3.10/site-packages/ipaserver/install/service.py", line 862, in request_service_keytab
    self.run_getkeytab(self.api.env.ldap_uri, self.keytab, self.principal)
  File "/usr/lib/python3.10/site-packages/ipaserver/install/service.py", line 852, in run_getkeytab
    ipautil.run(args, nolog=nolog)
  File "/usr/lib/python3.10/site-packages/ipapython/ipautil.py", line 599, in run
    raise CalledProcessError(
ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/usr/sbin/ipa-getkeytab', '-k', '/var/lib/ipa/gssproxy/http.keytab', '-p', 'HTTP/replica2.ipa.test@IPA.TEST', '-H', 'ldapi://%2Frun%2Fslapd-IPA-TEST.socket', '-Y', 'EXTERNAL'] returned non-zero exit status 9: 'Failed to parse result: Internal error while encrypting keys\n\nRetrying with pre-4.0 keytab retrieval method...\nFailed to parse result: Internal error.\n\nFailed to get keytab!\nFailed to get keytab\n')

ipa-getkeytab command performs a LDAP extended op 2.16.840.1.113730.3.8.10.5 on the local machine (dirsrv access):

[25/Aug/2022:01:22:26.949480717 +0000] conn=4 fd=65 slot=65 connection from local to /run/slapd-IPA-TEST.socket
[25/Aug/2022:01:22:26.951848843 +0000] conn=4 AUTOBIND dn="cn=Directory Manager"
[25/Aug/2022:01:22:26.953704745 +0000] conn=4 op=0 BIND dn="cn=Directory Manager" method=sasl version=3 mech=EXTERNAL
[25/Aug/2022:01:22:26.956212799 +0000] conn=4 op=1 EXT oid="2.16.840.1.113730.3.8.10.5" name="IPA Password Manager"
[25/Aug/2022:01:22:26.956386260 +0000] conn=4 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.000066873 optime=0.004689558 etime=0.004751736 dn="cn=Directory Manager"
[25/Aug/2022:01:22:26.973603878 +0000] conn=4 op=1 RESULT err=1 tag=120 nentries=0 wtime=0.000087741 optime=0.017402587 etime=0.017485873
[25/Aug/2022:01:22:26.973157110 +0000] conn=4 op=2 UNBIND
[25/Aug/2022:01:22:26.991122318 +0000] conn=4 op=2 fd=65 Disconnect - Cleanly Closed Connection - U1

If it fails tries with an older method using the LDAP extended op 2.16.840.1.113730.3.8.10.1 (dirsrv access):

[25/Aug/2022:01:22:26.972719165 +0000] conn=5 fd=66 slot=66 connection from local to /run/slapd-IPA-TEST.socket
[25/Aug/2022:01:22:26.974313511 +0000] conn=5 AUTOBIND dn="cn=Directory Manager"
[25/Aug/2022:01:22:26.975481568 +0000] conn=5 op=0 BIND dn="cn=Directory Manager" method=sasl version=3 mech=EXTERNAL
[25/Aug/2022:01:22:26.977160305 +0000] conn=5 op=1 EXT oid="2.16.840.1.113730.3.8.10.1" name="IPA Password Manager"
[25/Aug/2022:01:22:26.990242906 +0000] conn=5 op=2 UNBIND

Both methods fail.

The dirsrv error log shows a Cryptosystem internal error at the time the 1st ext op is handled:

Aug 25 01:22:26 replica2.ipa.test ns-slapd[9552]: [25/Aug/2022:01:22:26.965108918 +0000] - ERR - ipapwd_encrypt_encode_key - [file encoding.c, line 179]: generating kerberos keys failed [Cryptosystem internal error]
Aug 25 01:22:26 replica2.ipa.test ns-slapd[9552]: [25/Aug/2022:01:22:26.968058336 +0000] - ERR - ipapwd_getkeytab - [file ipa_pwd_extop.c, line 1747]: encrypt_encode_keys failed!

The corresponding code is in the plugin ipa-pwd-extop:

https://github.com/freeipa/freeipa/blob/06183a061a00b9f9b36107d3e3d1e6c81cdf5146/daemons/ipa-slapi-plugins/ipa-pwd-extop/encoding.c#L174-L182

Need to understand in which case this method could return KRB5_CRYPTO_INTERNAL.


Also happened in fedora-previous/test_replica_promotion_TestHiddenReplicaKRA in PR#2201, with 389-ds-base-2.1.1-2.fc36.x86_64 + freeipa master branch + openssl-3.0.3-1.fc36 (logs)

Also seen in fedora-latest/test_pwpolicy in PR#2204, with 389-ds-base-2.2.3-1.fc37 + freeipa master branch + openssl-3.0.5-2.fc37 (logs)

Also seen in fedora-latest-ipa-4-10/test_installation_TestInstallWithoutNamed in PR #2205, with 389-ds-base-2.2.3-1.fc37 + freeipa ipa-4-10 branch + openssl-3.0.5-2.fc37 (logs

Also seen in fedora-latest/test_pkinit_manage in PR #2275 with 389-ds-base-2.2.3-1.fc37.x86_64 + freeipa master branch + openssl-3.0.5-3.fc37.x86_64 9logs)

Login to comment on this ticket.

Metadata