pkispawn currently has hardcoded timeout of 60s when waiting for first startup of server. In a slow environment (e.g. FreeIPA upstream CI) this limit can be exceeded, causing spurious failure.
We need a way to override this timeout. See below discussion:
On 08/21/2017 03:19 AM, Fraser Tweedale wrote:
On Thu, Aug 17, 2017 at 04:45:34PM +0200, Tomas Krizek wrote: This is becoming an increasingly pressing issue. Our ABCDE lab is having performance issues since yesterday which leads to this failure on almost every PR. Ideally, everything should just slow down, but this hard limit on dogtag restart is quite aggressive and causes test failures. On 08/16/2017 02:53 PM, Tomas Krizek wrote: Hi Fraser, did you have any time to investigate this issue? It happens quite often during testing in our PR CI. It seems the server doesn't start within 1 minute after executing systemctl start pki-tomcatd pki-tomcat service I think it's likely that the server would start given enough time. We use nested virtualization and there's a significant performance degradation (2.5x slower than in lab), so it's possible increasing this timeout would solve the issue. Is there a place where this timeout could be configured? Thanks. On 08/02/2017 01:08 PM, Fraser Tweedale wrote: Hi Tomas, I've been busy preparing for PyCon AU and tomorrow I will be travelling to the conf. But I have not missed this and will give it my attention next week. Thank you, Fraser On Mon, Jul 31, 2017 at 02:00:19PM +0200, Tomas Krizek wrote: Hi, during stress testing of our Pull-Request CI, I encountered the following heisenbug. During ipa-server-install or ipa-replica-install, dogtag sometimes fails to start in time [1]. I encountered this issue in both ipa-4-5 and master branch with pki 10.4.7-1. It seems to happen about once in 50 times. I've seen this issue when dogtag doesn't have enough memory, but the VMs have 3GB available. Could you please take a look at the logs [2] if you can find any useful info of what might be the cause? Is there an upstream issue for this? Thanks! [1] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/test_integration-test_simple_replication.py-TestSimpleReplication-()-test_user_replication_to_replica/master.ipa.test/var/log/pki/pki-ca-spawn.20170730070521.log.gz [2] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/ -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 Hi Tomas (& team), We don't seem to have ever hit this issue in the "real world" AFAIK. The busy, nested virt environment seem to be the main factor. The limit of 60 seconds is hardcoded in pkispawn, so will need a new build of Dogtag to relax it. Tomas, would updating pkispawn to recognise an environment variable for overriding the timeout be a sufficient fix? If we take this approach, in addition to the change in Dogtag, I suppose it will be necessary to update the CI scripts to set the env var. What do you think? Using an environment variable should work just fine. We can modify our CI to set a longer timeout with this variable.
On Thu, Aug 17, 2017 at 04:45:34PM +0200, Tomas Krizek wrote:
This is becoming an increasingly pressing issue. Our ABCDE lab is having performance issues since yesterday which leads to this failure on almost every PR. Ideally, everything should just slow down, but this hard limit on dogtag restart is quite aggressive and causes test failures. On 08/16/2017 02:53 PM, Tomas Krizek wrote: Hi Fraser, did you have any time to investigate this issue? It happens quite often during testing in our PR CI. It seems the server doesn't start within 1 minute after executing systemctl start pki-tomcatd pki-tomcat service I think it's likely that the server would start given enough time. We use nested virtualization and there's a significant performance degradation (2.5x slower than in lab), so it's possible increasing this timeout would solve the issue. Is there a place where this timeout could be configured? Thanks. On 08/02/2017 01:08 PM, Fraser Tweedale wrote: Hi Tomas, I've been busy preparing for PyCon AU and tomorrow I will be travelling to the conf. But I have not missed this and will give it my attention next week. Thank you, Fraser On Mon, Jul 31, 2017 at 02:00:19PM +0200, Tomas Krizek wrote: Hi, during stress testing of our Pull-Request CI, I encountered the following heisenbug. During ipa-server-install or ipa-replica-install, dogtag sometimes fails to start in time [1]. I encountered this issue in both ipa-4-5 and master branch with pki 10.4.7-1. It seems to happen about once in 50 times. I've seen this issue when dogtag doesn't have enough memory, but the VMs have 3GB available. Could you please take a look at the logs [2] if you can find any useful info of what might be the cause? Is there an upstream issue for this? Thanks! [1] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/test_integration-test_simple_replication.py-TestSimpleReplication-()-test_user_replication_to_replica/master.ipa.test/var/log/pki/pki-ca-spawn.20170730070521.log.gz [2] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/ -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 Hi Tomas (& team),
This is becoming an increasingly pressing issue. Our ABCDE lab is having performance issues since yesterday which leads to this failure on almost every PR. Ideally, everything should just slow down, but this hard limit on dogtag restart is quite aggressive and causes test failures.
On 08/16/2017 02:53 PM, Tomas Krizek wrote:
Hi Fraser, did you have any time to investigate this issue? It happens quite often during testing in our PR CI. It seems the server doesn't start within 1 minute after executing systemctl start pki-tomcatd pki-tomcat service I think it's likely that the server would start given enough time. We use nested virtualization and there's a significant performance degradation (2.5x slower than in lab), so it's possible increasing this timeout would solve the issue. Is there a place where this timeout could be configured? Thanks. On 08/02/2017 01:08 PM, Fraser Tweedale wrote: Hi Tomas, I've been busy preparing for PyCon AU and tomorrow I will be travelling to the conf. But I have not missed this and will give it my attention next week. Thank you, Fraser On Mon, Jul 31, 2017 at 02:00:19PM +0200, Tomas Krizek wrote: Hi, during stress testing of our Pull-Request CI, I encountered the following heisenbug. During ipa-server-install or ipa-replica-install, dogtag sometimes fails to start in time [1]. I encountered this issue in both ipa-4-5 and master branch with pki 10.4.7-1. It seems to happen about once in 50 times. I've seen this issue when dogtag doesn't have enough memory, but the VMs have 3GB available. Could you please take a look at the logs [2] if you can find any useful info of what might be the cause? Is there an upstream issue for this? Thanks! [1] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/test_integration-test_simple_replication.py-TestSimpleReplication-()-test_user_replication_to_replica/master.ipa.test/var/log/pki/pki-ca-spawn.20170730070521.log.gz [2] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/ -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 -- Tomas Krizek
Hi Fraser,
did you have any time to investigate this issue? It happens quite often during testing in our PR CI.
It seems the server doesn't start within 1 minute after executing
systemctl start pki-tomcatd pki-tomcat service
I think it's likely that the server would start given enough time. We use nested virtualization and there's a significant performance degradation (2.5x slower than in lab), so it's possible increasing this timeout would solve the issue.
Is there a place where this timeout could be configured?
Thanks.
On 08/02/2017 01:08 PM, Fraser Tweedale wrote:
Hi Tomas, I've been busy preparing for PyCon AU and tomorrow I will be travelling to the conf. But I have not missed this and will give it my attention next week. Thank you, Fraser On Mon, Jul 31, 2017 at 02:00:19PM +0200, Tomas Krizek wrote: Hi, during stress testing of our Pull-Request CI, I encountered the following heisenbug. During ipa-server-install or ipa-replica-install, dogtag sometimes fails to start in time [1]. I encountered this issue in both ipa-4-5 and master branch with pki 10.4.7-1. It seems to happen about once in 50 times. I've seen this issue when dogtag doesn't have enough memory, but the VMs have 3GB available. Could you please take a look at the logs [2] if you can find any useful info of what might be the cause? Is there an upstream issue for this? Thanks! [1] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/test_integration-test_simple_replication.py-TestSimpleReplication-()-test_user_replication_to_replica/master.ipa.test/var/log/pki/pki-ca-spawn.20170730070521.log.gz [2] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/ -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 -- Tomas Krizek
Hi Tomas,
I've been busy preparing for PyCon AU and tomorrow I will be travelling to the conf. But I have not missed this and will give it my attention next week.
Thank you, Fraser
On Mon, Jul 31, 2017 at 02:00:19PM +0200, Tomas Krizek wrote:
Hi, during stress testing of our Pull-Request CI, I encountered the following heisenbug. During ipa-server-install or ipa-replica-install, dogtag sometimes fails to start in time [1]. I encountered this issue in both ipa-4-5 and master branch with pki 10.4.7-1. It seems to happen about once in 50 times. I've seen this issue when dogtag doesn't have enough memory, but the VMs have 3GB available. Could you please take a look at the logs [2] if you can find any useful info of what might be the cause? Is there an upstream issue for this? Thanks! [1] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/test_integration-test_simple_replication.py-TestSimpleReplication-()-test_user_replication_to_replica/master.ipa.test/var/log/pki/pki-ca-spawn.20170730070521.log.gz [2] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/ -- Tomas Krizek PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869 -- Tomas Krizek
Hi,
during stress testing of our Pull-Request CI, I encountered the following heisenbug.
During ipa-server-install or ipa-replica-install, dogtag sometimes fails to start in time [1]. I encountered this issue in both ipa-4-5 and master branch with pki 10.4.7-1. It seems to happen about once in 50 times.
I've seen this issue when dogtag doesn't have enough memory, but the VMs have 3GB available. Could you please take a look at the logs [2] if you can find any useful info of what might be the cause? Is there an upstream issue for this?
Thanks!
[1] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/test_integration-test_simple_replication.py-TestSimpleReplication-()-test_user_replication_to_replica/master.ipa.test/var/log/pki/pki-ca-spawn.20170730070521.log.gz [2] - https://fedorapeople.org/groups/freeipa/prci/jobs/70f10c12-74f4-11e7-9da8-001a4a23162a/
-- Tomas Krizek
PGP: 4A8B A48C 2AED 933B D495 C509 A1FB A5F7 EF8C 4869
Hi Tomas (& team),
We don't seem to have ever hit this issue in the "real world" AFAIK. The busy, nested virt environment seem to be the main factor.
The limit of 60 seconds is hardcoded in pkispawn, so will need a new build of Dogtag to relax it.
Tomas, would updating pkispawn to recognise an environment variable for overriding the timeout be a sufficient fix? If we take this approach, in addition to the change in Dogtag, I suppose it will be necessary to update the CI scripts to set the env var.
What do you think? Using an environment variable should work just fine. We can modify our CI to set a longer timeout with this variable.
Gerrit review: https://review.gerrithub.io/#/c/375055/
COPR: https://copr.fedorainfracloud.org/coprs/ftweedal/pki-pkispawn-override-timeout
Metadata Update from @ftweedal: - Custom field component adjusted to None - Custom field feature adjusted to None - Custom field origin adjusted to None - Custom field proposedmilestone adjusted to None - Custom field proposedpriority adjusted to None - Custom field reviewer adjusted to None - Custom field type adjusted to None - Custom field version adjusted to None
Metadata Update from @mharmsen: - Issue set to the milestone: 0.0 NEEDS_TRIAGE
Metadata Update from @mharmsen: - Issue set to the milestone: 10.5 (was: 0.0 NEEDS_TRIAGE)
Merged to master: 6d23ffddfa52549a6358ac8175282a42ab79887f
Metadata Update from @ftweedal: - Issue set to the milestone: 0.0 NEEDS_TRIAGE (was: 10.5)
Metadata Update from @ftweedal: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Metadata Update from @mharmsen: - Issue priority set to: major - Issue set to the milestone: 10.5 (was: 0.0 NEEDS_TRIAGE)
Metadata Update from @mharmsen: - Issue assigned to ftweedal
Metadata Update from @mharmsen: - Issue set to the milestone: 10.5.0 (was: 10.5)
Metadata Update from @mharmsen: - Custom field fixedinversion adjusted to pki-core-10.5.0-1.fc27
Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.
This issue has been cloned to GitHub and is available here: https://github.com/dogtagpki/pki/issues/2915
If you want to receive further updates on the issue, please navigate to the GitHub issue and click on Subscribe button.
Subscribe
Thank you for understanding, and we apologize for any inconvenience.