I'm seeing an increasing amount of PR-CI failures cause by pkispawn timeout. The failures started around the same time as https://pagure.io/freeipa/c/83c173cf9d38d252caafcd40267bb1a67c78c1c9 for #7425 has landed.
Example: https://fedorapeople.org/groups/freeipa/prci/jobs/fbf2ebcc-30d4-11e8-ac99-fa163e333e4b/-TestInstallKRA--test_create_and_retrieve_vault_replica_without_kra/master.ipa.test/var/log/
2018-03-26 09:26:19 pkispawn : INFO ....... executing 'systemctl daemon-reload' 2018-03-26 09:26:20 pkispawn : INFO ....... executing 'systemctl start pki-tomcatd@pki-tomcat.service' 2018-03-26 09:27:23 pkispawn : INFO ........... checking https://master.ipa.test:8443/ca 2018-03-26 09:27:24 pkispawn : INFO ........... waiting for server to start (1s) 2018-03-26 09:27:25 pkispawn : INFO ........... waiting for server to start (2s) 2018-03-26 09:27:26 pkispawn : INFO ........... waiting for server to start (3s) 2018-03-26 09:27:27 pkispawn : INFO ........... waiting for server to start (4s) 2018-03-26 09:27:28 pkispawn : INFO ........... waiting for server to start (5s) 2018-03-26 09:27:29 pkispawn : INFO ........... waiting for server to start (6s) 2018-03-26 09:27:30 pkispawn : INFO ........... waiting for server to start (7s) 2018-03-26 09:27:31 pkispawn : INFO ........... waiting for server to start (8s) 2018-03-26 09:27:32 pkispawn : INFO ........... waiting for server to start (9s) 2018-03-26 09:27:33 pkispawn : INFO ........... waiting for server to start (10s) 2018-03-26 09:27:34 pkispawn : INFO ........... waiting for server to start (11s) 2018-03-26 09:27:35 pkispawn : INFO ........... waiting for server to start (12s) 2018-03-26 09:27:36 pkispawn : INFO ........... waiting for server to start (13s) 2018-03-26 09:27:37 pkispawn : INFO ........... waiting for server to start (14s) 2018-03-26 09:27:38 pkispawn : INFO ........... waiting for server to start (15s) 2018-03-26 09:27:39 pkispawn : INFO ........... waiting for server to start (16s) 2018-03-26 09:27:40 pkispawn : INFO ........... waiting for server to start (17s) 2018-03-26 09:27:41 pkispawn : INFO ........... waiting for server to start (18s) 2018-03-26 09:27:42 pkispawn : INFO ........... waiting for server to start (19s) 2018-03-26 09:27:43 pkispawn : INFO ........... waiting for server to start (20s) 2018-03-26 09:27:44 pkispawn : INFO ........... waiting for server to start (21s) 2018-03-26 09:27:45 pkispawn : INFO ........... waiting for server to start (22s) 2018-03-26 09:27:46 pkispawn : INFO ........... waiting for server to start (23s) 2018-03-26 09:28:02 pkispawn : DEBUG ....... Error Type: ReadTimeout 2018-03-26 09:28:02 pkispawn : DEBUG ....... Error Message: HTTPSConnectionPool(host='master.ipa.test', port=8443): Read timed out. (read timeout=15) 2018-03-26 09:28:02 pkispawn : DEBUG ....... File "/usr/lib/python2.7/site-packages/pki/server/pkispawn.py", line 533, in main scriptlet.spawn(deployer) File "/usr/lib/python2.7/site-packages/pki/server/deployment/scriptlets/configuration.py", line 1097, in spawn request_timeout=status_request_timeout, File "/usr/lib/python2.7/site-packages/pki/server/deployment/pkihelper.py", line 1081, in wait_for_startup timeout=request_timeout, File "/usr/lib/python2.7/site-packages/pki/server/deployment/pkihelper.py", line 1024, in get_instance_status response = client.get_status(timeout=timeout) File "/usr/lib/python2.7/site-packages/pki/system.py", line 298, in get_status timeout=timeout, File "/usr/lib/python2.7/site-packages/pki/client.py", line 46, in wrapper return func(self, *args, **kwargs) File "/usr/lib/python2.7/site-packages/pki/client.py", line 160, in get timeout=timeout, File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 521, in get return self.request('GET', url, **kwargs) File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 508, in request resp = self.send(prep, **send_kwargs) File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 618, in send r = adapter.send(request, **kwargs) File "/usr/lib/python2.7/site-packages/requests/adapters.py", line 521, in send raise ReadTimeout(e, request=request)
@ftweedal please take a look
Now it's even failing in our test lab. I'm bumping priority to 4.7 blocker.
2018-03-26 17:45:23 pkispawn : INFO ....... executing 'systemctl daemon-reload' 2018-03-26 17:45:24 pkispawn : INFO ....... executing 'systemctl start pki-tomcatd@pki-tomcat.service' 2018-03-26 17:45:44 pkispawn : INFO ........... checking https://master.ipa.example:8443/ca 2018-03-26 17:45:45 pkispawn : INFO ........... waiting for server to start (1s) 2018-03-26 17:45:46 pkispawn : INFO ........... waiting for server to start (2s) 2018-03-26 17:45:47 pkispawn : INFO ........... waiting for server to start (3s) 2018-03-26 17:45:48 pkispawn : INFO ........... waiting for server to start (4s) 2018-03-26 17:45:49 pkispawn : INFO ........... waiting for server to start (5s) 2018-03-26 17:45:50 pkispawn : INFO ........... waiting for server to start (6s) 2018-03-26 17:45:51 pkispawn : INFO ........... waiting for server to start (7s) 2018-03-26 17:45:52 pkispawn : INFO ........... waiting for server to start (8s) 2018-03-26 17:46:08 pkispawn : DEBUG ....... Error Type: ReadTimeout 2018-03-26 17:46:08 pkispawn : DEBUG ....... Error Message: HTTPSConnectionPool(host='master.ipa.example', port=8443): Read timed out. (read timeout=15) 2018-03-26 17:46:08 pkispawn : DEBUG ....... File "/usr/lib/python3.6/site-packages/pki/server/pkispawn.py", line 533, in main scriptlet.spawn(deployer) File "/usr/lib/python3.6/site-packages/pki/server/deployment/scriptlets/configuration.py", line 1097, in spawn request_timeout=status_request_timeout, File "/usr/lib/python3.6/site-packages/pki/server/deployment/pkihelper.py", line 1081, in wait_for_startup timeout=request_timeout, File "/usr/lib/python3.6/site-packages/pki/server/deployment/pkihelper.py", line 1024, in get_instance_status response = client.get_status(timeout=timeout) File "/usr/lib/python3.6/site-packages/pki/system.py", line 298, in get_status timeout=timeout, File "/usr/lib/python3.6/site-packages/pki/client.py", line 46, in wrapper return func(self, *args, **kwargs) File "/usr/lib/python3.6/site-packages/pki/client.py", line 160, in get timeout=timeout, File "/usr/lib/python3.6/site-packages/requests/sessions.py", line 521, in get return self.request('GET', url, **kwargs) File "/usr/lib/python3.6/site-packages/requests/sessions.py", line 508, in request resp = self.send(prep, **send_kwargs) File "/usr/lib/python3.6/site-packages/requests/sessions.py", line 618, in send r = adapter.send(request, **kwargs) File "/usr/lib/python3.6/site-packages/requests/adapters.py", line 521, in send raise ReadTimeout(e, request=request)
Metadata Update from @cheimes: - Issue priority set to: critical (was: important) - Issue set to the milestone: FreeIPA 4.7
The issue is likely caused by https://pagure.io/dogtagpki/issue/2973
Dogtag bug https://pagure.io/dogtagpki/issue/2973 has been fixed upstream.
I have build pki-core-10.6.0-0.2.20180327184846.353de17f in freeipa-master COPR ( https://copr.fedorainfracloud.org/coprs/g/freeipa/freeipa-master/build/733182/) to unblock the tests. The Dogtag team will release a new version soonish.
I haven't seen the problem in a while. It looks like latest Dogtag is fine again.
Metadata Update from @cheimes: - Issue assigned to cheimes - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Log in to comment on this ticket.