freeipa

#8714 Nightly test failure in test_integration/test_pkinit_manage.py::TestPkinitInstall::()::test_pkinit::setup
Closed: duplicate by frenaud. Opened by mpolovka.

Closed: duplicate
Reopen Issue

setup in test_integration/test_pkinit_manage.py::TestPkinitInstall::()::test_pkinit is failing in [testing_ipa-4.6] Nightly PR #716
with

E           subprocess.CalledProcessError: Command '['ipa-server-install', '-n', 'ipa.test', '-r', 'IPA.TEST', '-p', 'Secret.123', '-a', 'Secret.123', '--domain-level=1', '-U', '--setup-dns', '--forwarder', '192.168.122.1', '--auto-reverse']' returned non-zero exit status 1.

further logs show

[ipatests.pytest_ipa.integration.host.Host.master.cmd8]   [10/30]: starting certificate server instance
[ipatests.pytest_ipa.integration.host.Host.master.cmd8]   [11/30]: configure certmonger for renewals
[ipatests.pytest_ipa.integration.host.Host.master.cmd8]   [12/30]: requesting RA certificate from CA
[ipatests.pytest_ipa.integration.host.Host.master.cmd8]   [error] RuntimeError: request timed out
[ipatests.pytest_ipa.integration.host.Host.master.cmd8] Exit code: 1
ipa: ERROR: stderr: ipapython.admintool: ERROR    request timed out
ipapython.admintool: ERROR    The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information

and relevant part of /var/log/ipaserver-install.log shows

2021-02-14T16:37:28Z DEBUG stderr=
2021-02-14T16:37:28Z DEBUG Start of certmonger.service complete
2021-02-14T16:37:28Z DEBUG   duration: 0 seconds
2021-02-14T16:37:28Z DEBUG   [12/30]: requesting RA certificate from CA
2021-02-14T16:37:28Z DEBUG Starting external process
2021-02-14T16:37:28Z DEBUG args=/usr/bin/openssl pkcs7 -inform DER -print_certs -out /var/lib/ipa/tmp0o6n15od
2021-02-14T16:37:28Z DEBUG Process finished, return code=0
2021-02-14T16:37:28Z DEBUG stdout=
2021-02-14T16:37:28Z DEBUG stderr=
2021-02-14T16:37:28Z DEBUG Starting external process
2021-02-14T16:37:28Z DEBUG args=/usr/bin/openssl pkcs12 -nokeys -clcerts -in /root/ca-agent.p12 -out /var/lib/ipa/tmpo5dofvnn -passin file:/tmp/tmprkowjyzv
2021-02-14T16:37:29Z DEBUG Process finished, return code=0
2021-02-14T16:37:29Z DEBUG stdout=
2021-02-14T16:37:29Z DEBUG stderr=
2021-02-14T16:37:29Z DEBUG Starting external process
2021-02-14T16:37:29Z DEBUG args=/usr/bin/openssl pkcs12 -nodes -nocerts -in /root/ca-agent.p12 -out /var/lib/ipa/tmpezrliiec -passin file:/tmp/tmp9jj0gw58
2021-02-14T16:37:30Z DEBUG Process finished, return code=0
2021-02-14T16:37:30Z DEBUG stdout=
2021-02-14T16:37:30Z DEBUG stderr=
2021-02-14T16:37:31Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_READING_CERT', variant_level=1)
2021-02-14T16:37:36Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:37:41Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:37:46Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:37:51Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:37:56Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:01Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:06Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:11Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:16Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:21Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:26Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:31Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:36Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:41Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:46Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:51Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:38:56Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:01Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:06Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:11Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:16Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:21Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:26Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:31Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:36Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:41Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:46Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:51Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:39:56Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:01Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:06Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:11Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:16Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:21Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:26Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:31Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:36Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:41Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:46Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:51Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:40:56Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:01Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:06Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:11Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:16Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:21Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:26Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:31Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:36Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:41Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:46Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:51Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:41:56Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:01Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:06Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:11Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:16Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:21Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:26Z DEBUG certmonger request is in state dbus.String('NEED_KEYINFO_READ_PIN', variant_level=1)
2021-02-14T16:42:32Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 567, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 557, in run_step
    method()
  File "/usr/lib/python3.6/site-packages/ipaserver/install/cainstance.py", line 943, in __request_ra_certificate
    resubmit_timeout=api.env.replication_wait_timeout
  File "/usr/lib/python3.6/site-packages/ipalib/install/certmonger.py", line 332, in request_and_wait_for_cert
    state = wait_for_request(req_id, api.env.replication_wait_timeout)
  File "/usr/lib/python3.6/site-packages/ipalib/install/certmonger.py", line 709, in wait_for_request
    raise RuntimeError("request timed out")
RuntimeError: request timed out

Note: Time stamps from beginning of operation and timeout differ by 5 minutes.

Full logs

This is a duplicate of 8096

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

test-failure tests

None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.