FreeIPA Installation Failing During CA Restart

Question

I'm trying to set up a simple vagrant box for testing with FreeIPA. I'm using the CentOS 7 image, and installing minimal extra things to the box, and using a very simple FreeIPA definition to start with. I've tried doing it using simple shell commands, and I've also tried using ansible-freeipa. In both cases, I see the same error, although the frequency of it happening seems to differ. In the simple shell commands, it only fails about 50% of the time, but with Ansible it seems to be 100%.

The failure gives me an error like the following.

fatal: [ipaserver.test.hadoop.com]: FAILED! => {"changed": false, "module_stderr": "Shared connection to ipaserver.test.hadoop.com closed.\r\n", "module_stdout": "\u001b[?1034hTraceback (most recent call last):\r\n File "/root/.ansible/tmp/ansible-tmp-1583188576.27-186488091977372/AnsiballZ_ipaserver_setup_ca.py", line 102, in \r\n _ansiballz_main()\r\n File "/root/.ansible/tmp/ansible-tmp-1583188576.27-186488091977372/AnsiballZ_ipaserver_setup_ca.py", line 94, in _ansiballz_main\r\n invoke_module(zipped_mod, temp_path, ANSIBALLZ_PARAMS)\r\n File "/root/.ansible/tmp/ansible-tmp-1583188576.27-186488091977372/AnsiballZ_ipaserver_setup_ca.py", line 40, in invoke_module\r\n runpy.run_module(mod_name='ansible.modules.ipaserver_setup_ca', init_globals=None, run_name='main', alter_sys=True)\r\n File "/usr/lib64/python2.7/runpy.py", line 176, in run_module\r\n fname, loader, pkg_name)\r\n File "/usr/lib64/python2.7/runpy.py", line 82, in _run_module_code\r\n mod_name, mod_fname, mod_loader, pkg_name)\r\n File "/usr/lib64/python2.7/runpy.py", line 72, in _run_code\r\n exec code in run_globals\r\n File "/tmp/ansible_ipaserver_setup_ca_payload_Pc9wnM/ansible_ipaserver_setup_ca_payload.zip/ansible/modules/ipaserver_setup_ca.py", line 354, in \r\n File "/tmp/ansible_ipaserver_setup_ca_payload_Pc9wnM/ansible_ipaserver_setup_ca_payload.zip/ansible/modules/ipaserver_setup_ca.py", line 345, in main\r\n File "/usr/lib/python2.7/site-packages/ipaserver/install/ca.py", line 391, in install_step_1\r\n ca.start('pki-tomcat')\r\n File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 464, in start\r\n self.service.start(instance_name, capture_output=capture_output, wait=wait)\r\n File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 192, in start\r\n self.wait_until_running()\r\n File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 186, in wait_until_running\r\n raise RuntimeError('CA did not start in %ss' % timeout)\r\nRuntimeError: CA did not start in 300.0s\r\n", "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", "rc": 1}

Looking in /var/log/messages, I see that the error happened sometime between 23:25 and 23:27 system time. Based on the errors, this happens when the CA is being restarted. It seems to start properly the first time it is brought up.

Mar 2 23:25:42 localhost systemd: Stopped PKI Tomcat Server pki-tomcat.
Mar 2 23:25:43 localhost systemd: Starting PKI Tomcat Server pki-tomcat...
Mar 2 23:26:13 localhost pkidaemon: -----------------------
Mar 2 23:26:13 localhost pkidaemon: Banner is not installed
Mar 2 23:26:13 localhost pkidaemon: -----------------------
Mar 2 23:27:07 localhost pkidaemon: ----------------------
Mar 2 23:27:08 localhost pkidaemon: Enabled all subsystems
Mar 2 23:27:08 localhost pkidaemon: ----------------------
Mar 2 23:27:18 localhost systemd: [email protected] start-pre operation timed out. Terminating.
Mar 2 23:27:18 localhost systemd: Failed to start PKI Tomcat Server pki-tomcat.
Mar 2 23:27:18 localhost systemd: Unit [email protected] entered failed state.
Mar 2 23:27:18 localhost systemd: [email protected] failed.

When I look in the PKI logs, however, there is nothing in there during this timeframe. These are the last few lines in /var/log/pki/pki-ca-spawn.20200302231442.log:

2020-03-02 23:18:32 pkispawn : INFO END spawning subsystem 'CA' of instance 'pki-tomcat'
2020-03-02 23:18:32 pkispawn : INFO ... archiving configuration into '/var/log/pki/pki-tomcat/ca/archive/spawn_deployment.cfg.20200302231442'
2020-03-02 23:18:32 pkispawn : INFO ....... cp -p /etc/sysconfig/pki/tomcat/pki-tomcat/ca/deployment.cfg /var/log/pki/pki-tomcat/ca/archive/spawn_deployment.cfg.20200302231442
2020-03-02 23:18:32 pkispawn : DEBUG ........... chmod 660 /var/log/pki/pki-tomcat/ca/archive/spawn_deployment.cfg.20200302231442
2020-03-02 23:18:32 pkispawn : DEBUG ........... chown 17:17 /var/log/pki/pki-tomcat/ca/archive/spawn_deployment.cfg.20200302231442
2020-03-02 23:18:32 pkispawn : INFO ... archiving manifest into '/var/log/pki/pki-tomcat/ca/archive/spawn_manifest.20200302231442'
2020-03-02 23:18:32 pkispawn : INFO ....... cp -p /etc/sysconfig/pki/tomcat/pki-tomcat/ca/manifest /var/log/pki/pki-tomcat/ca/archive/spawn_manifest.20200302231442
2020-03-02 23:18:32 pkispawn : DEBUG ........... chmod 660 /var/log/pki/pki-tomcat/ca/archive/spawn_manifest.20200302231442
2020-03-02 23:18:32 pkispawn : DEBUG ........... chown 17:17 /var/log/pki/pki-tomcat/ca/archive/spawn_manifest.20200302231442

Same for /var/log/pki/pki-tomcat/ca/debug:

[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: getConn: mNumConns now 4
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: returnConn: mNumConns now 5
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: In LdapBoundConnFactory::getConn()
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: masterConn is connected: true
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: getConn: conn is connected true
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: getConn: mNumConns now 4
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: returnConn: mNumConns now 5
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: CMSServlet.java: renderTemplate
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: CMSServlet.java: xml parameter detected, returning xml
[02/Mar/2020:23:25:00][http-bio-8080-exec-14]: CMSServlet: curDate=Mon Mar 02 23:25:00 UTC 2020 id=caDisplayCertFromRequest time=144

/var/log/pki/pki-tomcat/ca/system has a few errors, but none from after 23:25:

0.localhost-startStop-1 - [02/Mar/2020:23:15:08 UTC] [13] [3] authz instance DirAclAuthz initialization failed and skipped, error=Property internaldb.ldapconn.port missing value
0.http-bio-8443-exec-3 - [02/Mar/2020:23:17:53 UTC] [3] [3] CASigningUnit: Object certificate not found. Error Certificate object not found
0.http-bio-8443-exec-3 - [02/Mar/2020:23:17:54 UTC] [11] [3] UGSubsystem: Get User Error netscape.ldap.LDAPException: error result (32); matchedDN = ou=People,o=ipaca
0.Thread-16 - [02/Mar/2020:23:25:00 UTC] [8] [3] Publishing: Could not publish certificate serial number 0x7. Error Failed to publish using rule: No rules enabled

I'm at a loss of what would be causing this. Any ideas? The vagrant file and hosts file are all located in the GitHub repo below: https://github.com/davidov541/HadoopOnVagrant/tree/AnsibleRetrofit/FreeIPA

Answer 1

The ansible error at the end:

'CA did not start in %ss' % timeout)\r\nRuntimeError: CA did not start in 300.0s\r\n"

This does me think of something it came up on the mailing list and it was fixed by setting the starting_timeout variable on a script to a higher value.

The solution is described here:

https://www.freeipa.org/page/HowTo/FreeIPA_on_banana_pi

Maybe something to try, I cannot guarantee it will fix it for you, but ...

Answer 2

I ended up increasing my vagrant box size to 2 GB to fix another issue I was seeing, and after recreating the box 10 - 20 times since yesterday, I've not seen the issue since. Based on that, I believe that the issue was due to tomcat not having enough memory to start like it needed to, leading to the behavior we saw.