Bug 1624606 - Running ipa-server-install fails with RuntimeError: request timed out
Summary: Running ipa-server-install fails with RuntimeError: request timed out
Keywords:
Status: CLOSED DUPLICATE of bug 1619573
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-09-02 08:57 UTC by Jan Pazdziora
Modified: 2018-09-04 13:26 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-09-04 13:26:38 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Jan Pazdziora 2018-09-02 08:57:54 UTC
Description of problem:

Running ipa-server-install in container fails at the step

  [27/28]: adding 'ipa' CA entry
  [28/28]: configuring certmonger renewal for lightweight CAs
Done configuring certificate server (pki-tomcatd).
Configuring directory server (dirsrv)
  [1/3]: configuring TLS for DS instance
  [error] RuntimeError: request timed out

Version-Release number of selected component (if applicable):

freeipa-server-4.7.0-1.fc29.x86_64
certmonger-0.79.6-2.fc29.x86_64

How reproducible:

Deterministic.

Steps to Reproduce:
1. Build container image from https://github.com/freeipa/freeipa-container with -f Dockerfile.freeipa-rawhide.
2. Run the container with

docker run -h ipa.example.test \
        --sysctl net.ipv6.conf.all.disable_ipv6=0 \
        --tmpfs /run --tmpfs /tmp -v /dev/urandom:/dev/random:ro -v /sys/fs/cgroup:/sys/fs/cgroup:ro \
        -v $(pwd)/data:/data:Z \
        -e PASSWORD=Secret123 "$IMAGE" \
        exit-on-finished -U -r EXAMPLE.TEST --setup-dns --no-forwarders --no-ntp 

Actual results:

  [22/28]: updating IPA configuration
  [23/28]: enabling CA instance
  [24/28]: migrating certificate profiles to LDAP
  [25/28]: importing IPA certificate profiles
  [26/28]: adding default CA ACL
  [27/28]: adding 'ipa' CA entry
  [28/28]: configuring certmonger renewal for lightweight CAs
Done configuring certificate server (pki-tomcatd).
Configuring directory server (dirsrv)
  [1/3]: configuring TLS for DS instance
  [error] RuntimeError: request timed out
FreeIPA server configuration failed.

Expected results:

ipa-server-install does not fail.

Additional info:

Notable from journal is
Sep 02 08:43:45 ipa.example.test ipa-submit[1569]: GSSAPI client step 1
Sep 02 08:43:45 ipa.example.test ipa-submit[1569]: GSSAPI client step 1
Sep 02 08:43:54 ipa.example.test systemd[1]: Started Certificate monitoring and PKI enrollment.
Sep 02 08:44:18 ipa.example.test certmonger[1690]: Certificate in file "/var/lib/ipa/ra-agent.pem" issued by CA and saved.
Sep 02 08:45:06 ipa.example.test certmonger[2451]: OSSLEVPSymmetricAlgorithm.cpp(543): EVP_DecryptFinal failed (0x00000000): error:06
065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt
Sep 02 08:45:06 ipa.example.test certmonger[2452]: OSSLEVPSymmetricAlgorithm.cpp(543): EVP_DecryptFinal failed (0x00000000): error:06
065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt
Sep 02 08:45:06 ipa.example.test certmonger[2453]: OSSLEVPSymmetricAlgorithm.cpp(543): EVP_DecryptFinal failed (0x00000000): error:06
065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt

The ipaserver-install.log ends with

2018-09-02T08:45:04Z DEBUG stdout=
2018-09-02T08:45:04Z DEBUG stderr=
2018-09-02T08:45:04Z DEBUG Starting external process
2018-09-02T08:45:04Z DEBUG args=['/usr/bin/certutil', '-d', 'sql:/etc/dirsrv/slapd-EXAMPLE-TEST/', '-A', '-n', 'EXAMPLE.TEST IPA CA', '-t', 'CT,C,C', '-a', '-f', '/etc/dirsrv/slapd-EXAMPLE-TEST/pwdfile.txt']
2018-09-02T08:45:04Z DEBUG Process finished, return code=0
2018-09-02T08:45:04Z DEBUG stdout=
2018-09-02T08:45:04Z DEBUG stderr=
2018-09-02T08:45:06Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_READING_KEYINFO', variant_level=1)
2018-09-02T08:45:11Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:45:16Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:45:21Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:45:26Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:45:31Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:45:37Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:45:42Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
[...]
2018-09-02T08:49:43Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:49:48Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:49:53Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:49:58Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:50:03Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_NEED_KEYINFO_READ_PIN', variant_level=1)
2018-09-02T08:50:10Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/ipaserver/install/service.py", line 605, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.7/site-packages/ipaserver/install/service.py", line 591, in run_step
    method()
  File "/usr/lib/python3.7/site-packages/ipaserver/install/dsinstance.py", line 856, in __enable_ssl
    resubmit_timeout=api.env.replication_wait_timeout
  File "/usr/lib/python3.7/site-packages/ipalib/install/certmonger.py", line 329, in request_and_wait_for_cert
    state = wait_for_request(req_id, api.env.replication_wait_timeout)
  File "/usr/lib/python3.7/site-packages/ipalib/install/certmonger.py", line 706, in wait_for_request
    raise RuntimeError("request timed out")
RuntimeError: request timed out

2018-09-02T08:50:10Z DEBUG   [error] RuntimeError: request timed out
2018-09-02T08:50:10Z DEBUG   File "/usr/lib/python3.7/site-packages/ipapython/admintool.py", line 179, in execute
    return_value = self.run()
  File "/usr/lib/python3.7/site-packages/ipapython/install/cli.py", line 347, in run
    return cfgr.run()
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 360, in run
    return self.execute()
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 386, in execute
    for rval in self._executor():
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.7/site-packages/six.py", line 693, in reraise
    raise value
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.7/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.7/site-packages/six.py", line 693, in reraise
    raise value
  File "/usr/lib/python3.7/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 655, in _configure
    next(executor)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 518, in _handle_exception
    self.__parent._handle_exception(exc_info)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.7/site-packages/six.py", line 693, in reraise
    raise value
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 515, in _handle_exception
    super(ComponentBase, self)._handle_exception(exc_info)
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.7/site-packages/six.py", line 693, in reraise
    raise value
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.7/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.7/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.7/site-packages/six.py", line 693, in reraise
    raise value
  File "/usr/lib/python3.7/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.7/site-packages/ipapython/install/common.py", line 65, in _install
    for unused in self._installer(self.parent):
  File "/usr/lib/python3.7/site-packages/ipaserver/install/server/__init__.py", line 602, in main
    master_install(self)
  File "/usr/lib/python3.7/site-packages/ipaserver/install/server/install.py", line 253, in decorated
    func(installer)
  File "/usr/lib/python3.7/site-packages/ipaserver/install/server/install.py", line 860, in install
    ds.enable_ssl()
  File "/usr/lib/python3.7/site-packages/ipaserver/install/dsinstance.py", line 358, in enable_ssl
    self.start_creation()
  File "/usr/lib/python3.7/site-packages/ipaserver/install/service.py", line 605, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.7/site-packages/ipaserver/install/service.py", line 591, in run_step
    method()
  File "/usr/lib/python3.7/site-packages/ipaserver/install/dsinstance.py", line 856, in __enable_ssl
    resubmit_timeout=api.env.replication_wait_timeout
  File "/usr/lib/python3.7/site-packages/ipalib/install/certmonger.py", line 329, in request_and_wait_for_cert
    state = wait_for_request(req_id, api.env.replication_wait_timeout)
  File "/usr/lib/python3.7/site-packages/ipalib/install/certmonger.py", line 706, in wait_for_request
    raise RuntimeError("request timed out")

2018-09-02T08:50:10Z DEBUG The ipa-server-install command failed, exception: RuntimeError: request timed out
2018-09-02T08:50:10Z ERROR request timed out
2018-09-02T08:50:10Z ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information

Comment 1 Rob Crittenden 2018-09-04 13:26:38 UTC
NSS crypto policy was updated to add p11-kit-proxy which makes visible additional tokens which certmonger does not currently handle properly. I'm working on it.

*** This bug has been marked as a duplicate of bug 1619573 ***


Note You need to log in before you can comment on or make changes to this bug.