#8270 Nightly test failure in test_backup_and_restore.py::TestBackupReinstallRestoreWithKRA::test_full_backup_reinstall_restore_with_vault
Closed: duplicate 17 days ago by frenaud. Opened 8 months ago by fcami.

logs contain:

DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558 Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [1/30]: configuring certificate server instance
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [2/30]: Add ipa-pki-wait-running
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [3/30]: secure AJP connector
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [4/30]: reindex attributes
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [5/30]: exporting Dogtag certificate store pin
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [6/30]: stopping certificate server instance to update CS.cfg
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [7/30]: backing up CS.cfg
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [8/30]: disabling nonces
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [9/30]: set up CRL publishing
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [10/30]: enable PKIX certificate path discovery and validation
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [11/30]: starting certificate server instance
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [12/30]: configure certmonger for renewals
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [13/30]: requesting RA certificate from CA
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558   [error] RuntimeError: Certificate issuance failed (TIMEOUT: None)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558 Certificate issuance failed (TIMEOUT: None)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:558 The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd78:transport.py:217 Exit code: 1

Full ipaserver-install.log contains:

2020-04-15T00:31:37Z DEBUG args=['/usr/bin/openssl', 'pkcs12', '-nocerts', '-in', '/root/ca-agent.p12', '-out', '/var/lib/ipa/tmpsi_bemln', '-passin', 'file:/tmp/tmpc2ev09hs', '-nodes']
2020-04-15T00:31:38Z DEBUG Process finished, return code=0
2020-04-15T00:31:38Z DEBUG stdout=
2020-04-15T00:31:38Z DEBUG stderr=
2020-04-15T00:31:39Z DEBUG certmonger request is in state dbus.String('GENERATING_KEY_PAIR', variant_level=1)
2020-04-15T00:31:44Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:31:49Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:31:54Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:31:59Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:04Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:09Z DEBUG wait_for_request raised request timed out
2020-04-15T00:32:09Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:32:09Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:32:19Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:24Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:29Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:34Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:39Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:44Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:32:49Z DEBUG wait_for_request raised request timed out
2020-04-15T00:32:49Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:32:49Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:32:59Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:04Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:09Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:14Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:19Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:24Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:29Z DEBUG wait_for_request raised request timed out
2020-04-15T00:33:29Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:33:29Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:33:39Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:44Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:49Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:54Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:33:59Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:04Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:09Z DEBUG wait_for_request raised request timed out
2020-04-15T00:34:09Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:34:09Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:34:19Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:24Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:29Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:34Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:39Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:44Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:34:49Z DEBUG wait_for_request raised request timed out
2020-04-15T00:34:49Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:34:49Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:34:59Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:04Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:09Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:14Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:19Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:24Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:29Z DEBUG wait_for_request raised request timed out
2020-04-15T00:35:29Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:35:29Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:35:39Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:44Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:49Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:54Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:35:59Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:04Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:09Z DEBUG wait_for_request raised request timed out
2020-04-15T00:36:09Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:36:09Z DEBUG 20200415003138 not in final state, continue waiting
2020-04-15T00:36:19Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:24Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:29Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:34Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:39Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:44Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2020-04-15T00:36:49Z DEBUG wait_for_request raised request timed out
2020-04-15T00:36:49Z DEBUG Cert request 20200415003138 failed: TIMEOUT (None)
2020-04-15T00:36:49Z DEBUG Request 20200415003138 reached resubmit deadline

Other (already opened) issues are similar, but this is the first time where this test is impacted.

Metadata Update from @fcami:
- Issue tagged with: test-failure, tests

8 months ago

Also happened in [testing_master_389ds] PR #391

Closing as a duplicate of https://pagure.io/freeipa/issue/8096 which has the same symptoms (certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)

Metadata Update from @frenaud:
- Issue close_status updated to: duplicate
- Issue status updated to: Closed (was: Open)

17 days ago

Login to comment on this ticket.

Metadata