freeipa

#8470 ipa-replica-install now failing where it used to succeed
Closed: worksforme by frenaud. Opened by jsf9k.

Closed: worksforme
Reopen Issue

Issue

ipa-replica-install is failing, where previously it passed.

Steps to Reproduce

Apologies for being so long-winded, but I am trying to explain exactly what I am doing from the beginning.

I have three FreeIPA servers in AWS called ipa0, ipa1, and ipa2. The three FreeIPA servers all replicate against each other and all three are advertised via DNS SRV records. When i first set up the three servers I first install ipa0 via ipa-server-install and then install ipa1 and ipa2 as replicas of ipa0 via ipa-replica-install. All three servers are identical, except that ipa0 is configured to be the CA renewal master and has the entire DNA range for user and group IDs. If ipa0 goes down, I can move the CA renewal master and the DNS range to ipa1 or ipa2 and everything continues working as before. This is all working great.

In keeping with the idea of treating servers like cattle instead of pets, when I want to upgrade the three FreeIPA servers I build a new AMI and completely replace them one at a time. To be explicit, I:

  1. Move the CA renewal master and DNS range to ipa1
  2. Delete ipa0 from the cluster via the web UI
  3. Destroy the EC2 instance that was ipa0
  4. Deploy a new EC2 instance that will be the new ipa0
  5. Run ipa-replica-install on the new ipa0 to make it a replica of ipa1 or ipa2
  6. Reinstate any missing replication "connections"
  7. Move the CA renewal master and DNS range back to ipa0

Next I perform steps 2-6 for ipa1 and ipa2, making them replicas of ipa0. At this point I have three upgraded FreeIPA servers and all my data has been preserved. This process has worked for me a few times in the past.

Recently I tried to upgrade by deploying a new image with FreeIPA 4.8.7, but the ipa-replica-install command fails early, during the conncheck with the master:

2020-08-18T19:26:15Z DEBUG Starting external process
2020-08-18T19:26:15Z DEBUG args=['/usr/sbin/ipa-replica-conncheck', '--master', 'ipa0.staging.cool.cyber.dhs.gov', '--auto-master-check', '--realm', 'STAGING.COOL.CYBER.DHS.GOV', '--hostname', 'ipa2.staging.cool.cyber.dhs.gov', '--ca-cert-file', '/etc/ipa/ca.crt']
2020-08-18T19:26:43Z DEBUG Process finished, return code=1
2020-08-18T19:26:43Z DEBUG stdout=
2020-08-18T19:26:43Z DEBUG stderr=Check connection from replica to remote master 'ipa0.staging.cool.cyber.dhs.gov':
   Directory Service: Unsecure port (389): OK
   Directory Service: Secure port (636): OK
   Kerberos KDC: TCP (88): OK
   Kerberos Kpasswd: TCP (464): OK
   HTTP Server: Unsecure port (80): OK
   HTTP Server: Secure port (443): OK
The following list of ports use UDP protocol and would need to be
checked manually:
   Kerberos KDC: UDP (88): SKIPPED
   Kerberos Kpasswd: UDP (464): SKIPPED
Connection from replica to master is OK.
Start listening on required ports for remote master check
Get credentials to log in to remote master
Check RPC connection to remote master
Execute check on remote master
ERROR: Remote master check failed with following error message(s):
an internal error has occurred
2020-08-18T19:26:43Z DEBUG   File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 179, in execute
    return_value = self.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/cli.py", line 340, in run
    return cfgr.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 358, in run
    self.validate()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 368, in validate
    for _nothing in self._validator():
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 455, in _handle_validate_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 633, in _configure
    next(validator)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 455, in _handle_validate_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 518, in _handle_exception
    self.__parent._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 515, in _handle_exception
    super(ComponentBase, self)._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.8/site-packages/ipapython/install/common.py", line 65, in _install
    for unused in self._installer(self.parent):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/__init__.py", line 600, in main
    replica_promote_check(self)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 402, in decorated
    func(installer)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 424, in decorated
    func(installer)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 1169, in promote_check
    replica_conn_check(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 126, in replica_conn_check
    raise ScriptError(
2020-08-18T19:26:43Z DEBUG The ipa-replica-install command failed, exception: ScriptError: Connection check failed!
See /var/log/ipareplica-conncheck.log for more information.
If the check results are not valid it can be skipped with --skip-conncheck parameter.
2020-08-18T19:26:43Z ERROR Connection check failed!
See /var/log/ipareplica-conncheck.log for more information.
If the check results are not valid it can be skipped with --skip-conncheck parameter.
2020-08-18T19:26:43Z ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information

Note that the output indicates that the conncheck passed, but then something goes awry.

I have also tried upgrading ipa0 (via dnf upgrade) and re-running the install on ipa2, in case there is some clash between FreeIPA 4.8.6 and 4.8.7, but I see the same behavior.

Actual behavior

ipa-replica-install fails.

Expected behavior

ipa-replica-install should succeed.

Version/Release/Distribution

$ sudo rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server
freeipa-server-4.8.7-1.fc32.x86_64
freeipa-client-4.8.7-1.fc32.x86_64
package ipa-server is not installed
package ipa-client is not installed
389-ds-base-1.4.3.12-1.fc32.x86_64
pki-ca-10.9.0-0.4.fc32.noarch
krb5-server-1.18.2-20.fc32.x86_64

Additional info:

Any additional information, configuration, data or log snippets that is needed for reproduction or investigation of the issue.

Log file locations: https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/7/html/Linux_Domain_Identity_Authentication_and_Policy_Guide/config-files-logs.html
Troubleshooting guide: https://www.freeipa.org/page/Troubleshooting

I have also tried adding --skip-conncheck to the ipa-replica-install command-line arguments, but then ipa-replica-install fails later, basically hanging when the initial replication takes place. I get this output:

Disabled p11-kit-proxy
Configuring directory server (dirsrv). Estimated time: 30 seconds
  [1/41]: creating directory server instance
  [2/41]: configure autobind for root
  [3/41]: stopping directory server
  [4/41]: updating configuration in dse.ldif
  [5/41]: starting directory server
  [6/41]: adding default schema
  [7/41]: enabling memberof plugin
  [8/41]: enabling winsync plugin
  [9/41]: configure password logging
  [10/41]: configuring replication version plugin
  [11/41]: enabling IPA enrollment plugin
  [12/41]: configuring uniqueness plugin
  [13/41]: configuring uuid plugin
  [14/41]: configuring modrdn plugin
  [15/41]: configuring DNS plugin
  [16/41]: enabling entryUSN plugin
  [17/41]: configuring lockout plugin
  [18/41]: configuring topology plugin
  [19/41]: creating indices
  [20/41]: enabling referential integrity plugin
  [21/41]: configuring certmap.conf
  [22/41]: configure new location for managed entries
  [23/41]: configure dirsrv ccache and keytab
  [24/41]: enabling SASL mapping fallback
  [25/41]: restarting directory server
  [26/41]: creating DS keytab
  [27/41]: ignore time skew for initial replication
  [28/41]: setting up initial replication
Starting replication, please wait until this has completed.
Update in progress, 735 seconds elapsed
[ldap://ipa0.staging.cool.cyber.dhs.gov:389] reports: Update failed! Status: [Error (-1) - LDAP error: Can't contact LDAP server - no response received]
  [error] RuntimeError: Failed to start replication
Your system may be partly configured.
Run /usr/sbin/ipa-server-install --uninstall to clean up.
Failed to start replication
The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information

This is what appears in ipareplica-install.log:

2020-08-19T02:41:19Z DEBUG Fetching nsDS5ReplicaId from master [attempt 1/5]
2020-08-19T02:41:19Z DEBUG retrieving schema for SchemaCache url=ldap://ipa0.staging.cool.cyber.dhs.gov:389 conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7f1b1f8700a0>
2020-08-19T02:41:19Z DEBUG Successfully updated nsDS5ReplicaId.
2020-08-19T02:41:19Z DEBUG Add or update replica config cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config
2020-08-19T02:41:19Z DEBUG Added replica config cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config
2020-08-19T02:41:19Z DEBUG Add or update replica config cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config
2020-08-19T02:41:19Z DEBUG No update to cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config necessary
2020-08-19T02:41:19Z DEBUG Waiting up to 300 seconds for replication (ldapi://%2Frun%2Fslapd-STAGING-COOL-CYBER-DHS-GOV.socket) cn=meToipa0.staging.cool.cyber.dhs.gov,cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config (objectclass=*)
2020-08-19T02:41:19Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=meToipa0.staging.cool.cyber.dhs.gov,cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config'), {'objectClass': [b'nsds5replicationagreement', b'top'], 'cn': [b'meToipa0.staging.cool.cyber.dhs.gov'], 'nsDS5ReplicaHost': [b'ipa0.staging.cool.cyber.dhs.gov'], 'nsDS5ReplicaPort': [b'389'], 'nsds5replicaTimeout': [b'120'], 'nsDS5ReplicaRoot': [b'dc=staging,dc=cool,dc=cyber,dc=dhs,dc=gov'], 'description': [b'me to ipa0.staging.cool.cyber.dhs.gov'], 'nsDS5ReplicatedAttributeList': [b'(objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsDS5ReplicaTransportInfo': [b'LDAP'], 'nsDS5ReplicaBindMethod': [b'SASL/GSSAPI'], 'nsds5ReplicaStripAttrs': [b'modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp'], 'nsDS5ReplicatedAttributeListTotal': [b'(objectclass=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsds5replicareapactive': [b'0'], 'nsds5replicaLastUpdateStart': [b'19700101000000Z'], 'nsds5replicaLastUpdateEnd': [b'19700101000000Z'], 'nsds5replicaChangesSentSinceStartup': [b''], 'nsds5replicaLastUpdateStatus': [b'Error (0) No replication sessions started since server startup'], 'nsds5replicaLastUpdateStatusJSON': [b'{"state": "green", "ldap_rc": "0", "ldap_rc_text": "success", "repl_rc": "0", "repl_rc_text": "replica acquired", "date": "2020-08-19T02:41:19Z", "message": "Error (0) No replication sessions started since server startup"}'], 'nsds5replicaUpdateInProgress': [b'FALSE'], 'nsds5replicaLastInitStart': [b'19700101000000Z'], 'nsds5replicaLastInitEnd': [b'19700101000000Z']})]
2020-08-19T02:54:37Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 423, in __setup_replica
    repl.setup_promote_replication(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 1862, in setup_promote_replication
    raise RuntimeError("Failed to start replication")
RuntimeError: Failed to start replication
2020-08-19T02:54:37Z DEBUG   [error] RuntimeError: Failed to start replication
2020-08-19T02:54:37Z DEBUG Destroyed connection context.ldap2_139754500054176
2020-08-19T02:54:37Z DEBUG Backing up system configuration file '/etc/ipa/default.conf'
2020-08-19T02:54:37Z DEBUG Saving Index File to '/var/lib/ipa/sysrestore/sysrestore.index'
2020-08-19T02:54:37Z DEBUG Writing configuration file /etc/ipa/default.conf
2020-08-19T02:54:37Z DEBUG [global]
basedn = dc=staging,dc=cool,dc=cyber,dc=dhs,dc=gov
host = ipa2.staging.cool.cyber.dhs.gov
realm = STAGING.COOL.CYBER.DHS.GOV
domain = staging.cool.cyber.dhs.gov
xmlrpc_uri = https://ipa2.staging.cool.cyber.dhs.gov/ipa/xml
ldap_uri = ldapi://%2Frun%2Fslapd-STAGING-COOL-CYBER-DHS-GOV.socket
mode = production
enable_ra = True
ra_plugin = dogtag
dogtag_version = 10
2020-08-19T02:54:37Z DEBUG   File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 179, in execute
    return_value = self.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/cli.py", line 340, in run
    return cfgr.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 360, in run
    return self.execute()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 386, in execute
    for rval in self._executor():
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
2020-08-19T02:41:19Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=meToipa0.staging.cool.cyber.dhs.gov,cn=replica,cn=dc\=staging\,dc\=cool\,dc\=cyber\,dc\=dhs\,dc\=gov,cn=mapping tree,cn=config'), {'objectClass': [b'nsds5replicationagr
eement', b'top'], 'cn': [b'meToipa0.staging.cool.cyber.dhs.gov'], 'nsDS5ReplicaHost': [b'ipa0.staging.cool.cyber.dhs.gov'], 'nsDS5ReplicaPort': [b'389'], 'nsds5replicaTimeout': [b'120'], 'nsDS5ReplicaRoot': [b'dc=staging,dc=cool,dc=cyber,
dc=dhs,dc=gov'], 'description': [b'me to ipa0.staging.cool.cyber.dhs.gov'], 'nsDS5ReplicatedAttributeList': [b'(objectclass=*) $ EXCLUDE memberof idnssoaserial entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsDS5
ReplicaTransportInfo': [b'LDAP'], 'nsDS5ReplicaBindMethod': [b'SASL/GSSAPI'], 'nsds5ReplicaStripAttrs': [b'modifiersName modifyTimestamp internalModifiersName internalModifyTimestamp'], 'nsDS5ReplicatedAttributeListTotal': [b'(objectclass
=*) $ EXCLUDE entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount'], 'nsds5replicareapactive': [b'0'], 'nsds5replicaLastUpdateStart': [b'19700101000000Z'], 'nsds5replicaLastUpdateEnd': [b'19700101000000Z'], 'nsds5replicaC
hangesSentSinceStartup': [b''], 'nsds5replicaLastUpdateStatus': [b'Error (0) No replication sessions started since server startup'], 'nsds5replicaLastUpdateStatusJSON': [b'{"state": "green", "ldap_rc": "0", "ldap_rc_text": "success", "rep
l_rc": "0", "repl_rc_text": "replica acquired", "date": "2020-08-19T02:41:19Z", "message": "Error (0) No replication sessions started since server startup"}'], 'nsds5replicaUpdateInProgress': [b'FALSE'], 'nsds5replicaLastInitStart': [b'19
700101000000Z'], 'nsds5replicaLastInitEnd': [b'19700101000000Z']})]
2020-08-19T02:54:37Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 423, in __setup_replica
    repl.setup_promote_replication(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 1862, in setup_promote_replication
    raise RuntimeError("Failed to start replication")
RuntimeError: Failed to start replication
2020-08-19T02:54:37Z DEBUG   [error] RuntimeError: Failed to start replication
2020-08-19T02:54:37Z DEBUG Destroyed connection context.ldap2_139754500054176
2020-08-19T02:54:37Z DEBUG Backing up system configuration file '/etc/ipa/default.conf'
2020-08-19T02:54:37Z DEBUG Saving Index File to '/var/lib/ipa/sysrestore/sysrestore.index'
2020-08-19T02:54:37Z DEBUG Writing configuration file /etc/ipa/default.conf
2020-08-19T02:54:37Z DEBUG [global]
basedn = dc=staging,dc=cool,dc=cyber,dc=dhs,dc=gov
host = ipa2.staging.cool.cyber.dhs.gov
realm = STAGING.COOL.CYBER.DHS.GOV
domain = staging.cool.cyber.dhs.gov
xmlrpc_uri = https://ipa2.staging.cool.cyber.dhs.gov/ipa/xml
ldap_uri = ldapi://%2Frun%2Fslapd-STAGING-COOL-CYBER-DHS-GOV.socket
mode = production
enable_ra = True
ra_plugin = dogtag
dogtag_version = 10
2020-08-19T02:54:37Z DEBUG   File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 179, in execute
    return_value = self.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/cli.py", line 340, in run
    return cfgr.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 360, in run
    return self.execute()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 386, in execute
    for rval in self._executor():
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 655, in _configure
    next(executor)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 518, in _handle_exception
    self.__parent._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 515, in _handle_exception
    super(ComponentBase, self)._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.8/site-packages/ipapython/install/common.py", line 65, in _install
    for unused in self._installer(self.parent):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/__init__.py", line 602, in main
    replica_install(self)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 402, in decorated
    func(installer)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 1240, in install
    ds = install_replica_ds(config, options, ca_enabled,
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 100, in install_replica_ds
    ds.create_replica(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 391, in create_replica
    self.start_creation(runtime=30)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 423, in __setup_replica
    repl.setup_promote_replication(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/replication.py", line 1862, in setup_promote_replication
    raise RuntimeError("Failed to start replication")
2020-08-19T02:54:37Z DEBUG The ipa-replica-install command failed, exception: RuntimeError: Failed to start replication
2020-08-19T02:54:37Z ERROR Failed to start replication
2020-08-19T02:54:37Z ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information

Hi @jsf9k
Can you provide the output of /var/log/ipareplica-conncheck.log on ipa2, as well as the content of /var/log/httpd/error_log on ipa0 at the time the ipa-replica-install command was run? You should see a log with server_conncheck in error_log, maybe with more information.

If the message doesn't point you to anything specific, you can also enable debug logs on ipa0 by creating a file /etc/ipa/server.conf with the following content + restart apache:

# cat /etc/ipa/server.conf
[global]
debug = True
# systemctl restart httpd

This will log more information in /var/log/httpd/error_log. Retry the ipa2 replica installation without the --skip-conn-check option (you need first to run ipa-server-install --uninstall -U on ipa2, then ipa server-del ipa2 in ipa0), and gather the /var/log/httpd/error_log from ipa0.

Hi @frenaud,

Thanks for the quick response! I re-ran without the --skip-conncheck option. The file /var/log/ipareplica-conncheck.log on ipa2 contains this:

2020-08-19T14:13:28Z DEBUG /usr/sbin/ipa-replica-conncheck was invoked with options: {'master': 'ipa0.staging.cool.cyber.dhs.gov', 'auto_master_check': True, 'realm': 'STAGING.COOL.CYBER.DHS.GOV', 'kdc': None, 'principal': None, 'ca_cert_file': '/etc/ipa/ca.crt', 'replica': None, 'check_ca': False, 'hostname': 'ipa2.staging.cool.cyber.dhs.gov', 'debug': False, 'quiet': False, 'log_to_file': True}
2020-08-19T14:13:28Z DEBUG missing options might be asked for interactively later
2020-08-19T14:13:28Z DEBUG IPA version 4.8.7-1.fc32
2020-08-19T14:13:28Z INFO Check connection from replica to remote master 'ipa0.staging.cool.cyber.dhs.gov':
2020-08-19T14:13:28Z INFO    Directory Service: Unsecure port (389): OK
2020-08-19T14:13:28Z INFO    Directory Service: Secure port (636): OK
2020-08-19T14:13:28Z INFO    Kerberos KDC: TCP (88): OK
2020-08-19T14:13:28Z INFO    Kerberos Kpasswd: TCP (464): OK
2020-08-19T14:13:28Z INFO    HTTP Server: Unsecure port (80): OK
2020-08-19T14:13:28Z INFO    HTTP Server: Secure port (443): OK
2020-08-19T14:13:28Z INFO 
The following list of ports use UDP protocol and would need to be
checked manually:
2020-08-19T14:13:28Z INFO    Kerberos KDC: UDP (88): SKIPPED
2020-08-19T14:13:28Z INFO    Kerberos Kpasswd: UDP (464): SKIPPED
2020-08-19T14:13:28Z INFO 
Connection from replica to master is OK.
2020-08-19T14:13:28Z INFO Start listening on required ports for remote master check
2020-08-19T14:13:28Z DEBUG Starting listening thread.
2020-08-19T14:13:28Z DEBUG Original thread stopped
2020-08-19T14:13:28Z DEBUG 389 tcp: Started listening
2020-08-19T14:13:28Z DEBUG 636 tcp: Started listening
2020-08-19T14:13:28Z DEBUG 88 tcp: Started listening
2020-08-19T14:13:28Z DEBUG 88 udp: Started listening
2020-08-19T14:13:28Z DEBUG 464 tcp: Started listening
2020-08-19T14:13:28Z DEBUG 464 udp: Started listening
2020-08-19T14:13:28Z DEBUG 80 tcp: Started listening
2020-08-19T14:13:28Z DEBUG 443 tcp: Started listening
2020-08-19T14:13:28Z DEBUG Ports opened, notify original thread
2020-08-19T14:13:28Z DEBUG Original thread resumed
2020-08-19T14:13:28Z INFO Get credentials to log in to remote master
2020-08-19T14:13:28Z DEBUG KRB5CCNAME set to None
2020-08-19T14:13:28Z INFO Check RPC connection to remote master
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/bin/certutil', '-d', '/tmp/tmpla6h194g', '-N', '-f', '/tmp/tmpla6h194g/pwdfile.txt', '-@', '/tmp/tmpla6h194g/pwdfile.txt']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/sbin/restorecon', '-F', '/tmp/tmpla6h194g']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=Warning no default label for /tmp/tmpla6h194g
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/sbin/restorecon', '-F', '/tmp/tmpla6h194g/cert9.db']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=Warning no default label for /tmp/tmpla6h194g/cert9.db
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/sbin/restorecon', '-F', '/tmp/tmpla6h194g/key4.db']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=Warning no default label for /tmp/tmpla6h194g/key4.db
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/sbin/restorecon', '-F', '/tmp/tmpla6h194g/pkcs11.txt']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=Warning no default label for /tmp/tmpla6h194g/pkcs11.txt
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/sbin/restorecon', '-F', '/tmp/tmpla6h194g/pwdfile.txt']
2020-08-19T14:13:28Z DEBUG Process finished, return code=0
2020-08-19T14:13:28Z DEBUG stdout=Warning no default label for /tmp/tmpla6h194g/pwdfile.txt
2020-08-19T14:13:28Z DEBUG stderr=
2020-08-19T14:13:28Z DEBUG Starting external process
2020-08-19T14:13:28Z DEBUG args=['/usr/bin/certutil', '-d', 'sql:/tmp/tmpla6h194g', '-A', '-n', 'CN=Certificate Authority,O=STAGING.COOL.CYBER.DHS.GOV', '-t', 'C,,', '-a', '-f', '/tmp/tmpla6h194g/pwdfile.txt']
2020-08-19T14:13:29Z DEBUG Process finished, return code=0
2020-08-19T14:13:29Z DEBUG stdout=
2020-08-19T14:13:29Z DEBUG stderr=
2020-08-19T14:13:29Z DEBUG importing all plugin modules in ipaclient.remote_plugins.schema$872c1050...
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.remote_plugins.schema$872c1050.plugins
2020-08-19T14:13:29Z DEBUG importing all plugin modules in ipaclient.plugins...
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.automember
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.automount
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.ca
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.cert
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.certmap
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.certprofile
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.csrgen
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.dns
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.hbacrule
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.hbactest
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.host
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.idrange
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.internal
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.location
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.migration
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.misc
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.otptoken
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.otptoken_yubikey
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.passwd
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.permission
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.rpcclient
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.server
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.service
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.sudorule
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.topology
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.trust
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.user
2020-08-19T14:13:29Z DEBUG importing plugin module ipaclient.plugins.vault
2020-08-19T14:13:30Z DEBUG failed to find session_cookie in persistent storage for principal 'jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV'
2020-08-19T14:13:30Z DEBUG trying https://ipa0.staging.cool.cyber.dhs.gov/ipa/json
2020-08-19T14:13:30Z DEBUG Created connection context.rpcclient_139687711209216
2020-08-19T14:13:30Z DEBUG raw: ping(version='2.239')
2020-08-19T14:13:30Z DEBUG ping(version='2.239')
2020-08-19T14:13:30Z DEBUG [try 1]: Forwarding 'ping/1' to json server 'https://ipa0.staging.cool.cyber.dhs.gov/ipa/json'
2020-08-19T14:13:30Z DEBUG New HTTP connection (ipa0.staging.cool.cyber.dhs.gov)
2020-08-19T14:13:30Z DEBUG received Set-Cookie (<class 'list'>)'['ipa_session=MagBearerToken=28%2bUh4Pki3BFnU1xsJILPPJEC1XMMfzsZ%2f6PjjIbiGBjJH61lUdq1Kmc%2b%2f0zKKzjLMvIr3GCJSTzZz%2ff87T3jbBONSRDpR7%2bAf9GjoZgGIb1VRUEiS5lKhpk5nS7S1bsiQJrFglhZL8fVFfYKxyNGM49k36VUZjlvz%2fGeNAqjGaJNEa4%2bosiyK%2f2QVX%2fytmyMohQmM%2b1M7yE%2b0ZsBUo1PJw0YcSUwP4fJONoRAmY54kqcC8Y5szFoBaRlQYzw%2fMCmcA8GJkI8tLxXagfzXxSNmEP2oeVfvu1NDxoDLXYqRQ%3d;path=/ipa;httponly;secure;']'
2020-08-19T14:13:30Z DEBUG storing cookie 'ipa_session=MagBearerToken=28%2bUh4Pki3BFnU1xsJILPPJEC1XMMfzsZ%2f6PjjIbiGBjJH61lUdq1Kmc%2b%2f0zKKzjLMvIr3GCJSTzZz%2ff87T3jbBONSRDpR7%2bAf9GjoZgGIb1VRUEiS5lKhpk5nS7S1bsiQJrFglhZL8fVFfYKxyNGM49k36VUZjlvz%2fGeNAqjGaJNEa4%2bosiyK%2f2QVX%2fytmyMohQmM%2b1M7yE%2b0ZsBUo1PJw0YcSUwP4fJONoRAmY54kqcC8Y5szFoBaRlQYzw%2fMCmcA8GJkI8tLxXagfzXxSNmEP2oeVfvu1NDxoDLXYqRQ%3d;' for principal jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV
2020-08-19T14:13:30Z INFO Execute check on remote master
2020-08-19T14:13:30Z DEBUG [try 1]: Forwarding 'server_conncheck' to json server 'https://ipa0.staging.cool.cyber.dhs.gov/ipa/json'
2020-08-19T14:13:30Z DEBUG HTTP connection keep-alive (ipa0.staging.cool.cyber.dhs.gov)
2020-08-19T14:13:55Z DEBUG received Set-Cookie (<class 'list'>)'['ipa_session=MagBearerToken=Z98RnTNTraPqGyHaAPbrlKW0xBu1VozgmMttCbmKymayjCq%2fOgMmxQu7gPNtz7sFgu%2fw%2bKOPLe4QPf4cx6hIp47nftcVC4zYwOfUidAKDV21wtTnYOP6fSH%2bWPC9npSaoVoj8SF9YH2jV1ycx4mnpTfOeuMjeIVLovR5AfgIu9xmotcELQ3cTsbyxWjSxfvKgS3nlAPm2iqXMoj0zX4CPgLSv1vLJ4xJ9Mgxe5RhaJC5mkgp4GscWblytUK90xJ7ljmxww3mLE%2bpGRsklSrUa9PfVe3vCmajg0ZPV2etYgM%3d;path=/ipa;httponly;secure;']'
2020-08-19T14:13:55Z DEBUG storing cookie 'ipa_session=MagBearerToken=Z98RnTNTraPqGyHaAPbrlKW0xBu1VozgmMttCbmKymayjCq%2fOgMmxQu7gPNtz7sFgu%2fw%2bKOPLe4QPf4cx6hIp47nftcVC4zYwOfUidAKDV21wtTnYOP6fSH%2bWPC9npSaoVoj8SF9YH2jV1ycx4mnpTfOeuMjeIVLovR5AfgIu9xmotcELQ3cTsbyxWjSxfvKgS3nlAPm2iqXMoj0zX4CPgLSv1vLJ4xJ9Mgxe5RhaJC5mkgp4GscWblytUK90xJ7ljmxww3mLE%2bpGRsklSrUa9PfVe3vCmajg0ZPV2etYgM%3d;' for principal jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV
2020-08-19T14:13:55Z DEBUG Destroyed connection context.rpcclient_139687711209216
2020-08-19T14:13:55Z ERROR ERROR: Remote master check failed with following error message(s):
an internal error has occurred
2020-08-19T14:13:55Z DEBUG Stopping listening thread.
2020-08-19T14:13:55Z DEBUG 389 tcp: Stopped listening
2020-08-19T14:13:55Z DEBUG 636 tcp: Stopped listening
2020-08-19T14:13:55Z DEBUG 88 tcp: Stopped listening
2020-08-19T14:13:55Z DEBUG 88 udp: Stopped listening
2020-08-19T14:13:55Z DEBUG 464 tcp: Stopped listening
2020-08-19T14:13:55Z DEBUG 464 udp: Stopped listening
2020-08-19T14:13:55Z DEBUG 80 tcp: Stopped listening
2020-08-19T14:13:55Z DEBUG 443 tcp: Stopped listening

The file /var/log/httpd/error_log on ipa0 contains this:

[Wed Aug 19 14:13:17.962363 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:17.962417 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Wed Aug 19 14:13:17.972997 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: Created connection context.ldap2_140312891118784
[Wed Aug 19 14:13:17.973052 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:17.973363 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: raw: join('ipa2.staging.cool.cyber.dhs.gov', nshardwareplatform='x86_64', nsosversion='5.7.15-200.fc32.x86_64', version='2.51')
[Wed Aug 19 14:13:17.973463 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: join('ipa2.staging.cool.cyber.dhs.gov', realm='STAGING.COOL.CYBER.DHS.GOV', nshardwareplatform='x86_64', nsosversion='5.7.15-200.fc32.x86_64', version='2.51')
[Wed Aug 19 14:13:17.973946 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: raw: host_show('ipa2.staging.cool.cyber.dhs.gov', all=True, version='2.239')
[Wed Aug 19 14:13:17.974054 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: host_show('ipa2.staging.cool.cyber.dhs.gov', rights=False, all=True, raw=False, version='2.239', no_members=False)
[Wed Aug 19 14:13:17.978327 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: raw: host_add('ipa2.staging.cool.cyber.dhs.gov', force=True, version='2.239')
[Wed Aug 19 14:13:17.978473 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: host_add('ipa2.staging.cool.cyber.dhs.gov', random=False, force=True, no_reverse=False, all=False, raw=False, version='2.239', no_members=False)
[Wed Aug 19 14:13:17.996327 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: raw: config_show(version='2.239')
[Wed Aug 19 14:13:17.996440 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: config_show(rights=False, all=False, raw=False, version='2.239')
[Wed Aug 19 14:13:18.020688 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: INFO: [xmlserver] jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV: join('ipa2.staging.cool.cyber.dhs.gov', nshardwareplatform='x86_64', nsosversion='5.7.15-200.fc32.x86_64', version='2.51'): SUCCESS
[Wed Aug 19 14:13:18.021364 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38400] ipa: DEBUG: Destroyed connection context.ldap2_140312891118784
[Wed Aug 19 14:13:18.789227 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:18.789282 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:18.789320 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Wed Aug 19 14:13:18.901104 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: Created connection context.ldap2_140312891123072
[Wed Aug 19 14:13:18.901161 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:18.901373 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: raw: schema(version='2.170')
[Wed Aug 19 14:13:18.901443 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: schema(version='2.170')
[Wed Aug 19 14:13:18.901527 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: INFO: [jsonserver_kerb] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: schema(version='2.170'): SUCCESS
[Wed Aug 19 14:13:19.079789 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38412] ipa: DEBUG: Destroyed connection context.ldap2_140312891123072
[Wed Aug 19 14:13:20.302250 2020] [:warn] [pid 4210:tid 4419] [client 10.128.2.4:38416] failed to set perms (3140) on file (/run/ipa/ccaches/host~ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV)!, referer: https://ipa0.staging.cool.cyber.dhs.gov/ipa/xml
[Wed Aug 19 14:13:20.303017 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:20.303068 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Wed Aug 19 14:13:20.310027 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: Created connection context.ldap2_140312891118928
[Wed Aug 19 14:13:20.310193 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:20.310228 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:20.310535 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: raw: ping(version='2.239')
[Wed Aug 19 14:13:20.310793 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: ping(version='2.239')
[Wed Aug 19 14:13:20.310929 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: INFO: [jsonserver_session] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: ping(): SUCCESS
[Wed Aug 19 14:13:20.311612 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38416] ipa: DEBUG: Destroyed connection context.ldap2_140312891118928
[Wed Aug 19 14:13:20.313741 2020] [:warn] [pid 4210:tid 4411] [client 10.128.2.4:38416] failed to set perms (3140) on file (/run/ipa/ccaches/host~ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV)!, referer: https://ipa0.staging.cool.cyber.dhs.gov/ipa/xml
[Wed Aug 19 14:13:20.315533 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:20.315580 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Wed Aug 19 14:13:20.331470 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: Created connection context.ldap2_140312891123216
[Wed Aug 19 14:13:20.331528 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:20.331557 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:20.331793 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: raw: ca_is_enabled(version='2.107')
[Wed Aug 19 14:13:20.331864 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: ca_is_enabled(version='2.107')
[Wed Aug 19 14:13:20.337609 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: INFO: [jsonserver_session] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: ca_is_enabled(version='2.107'): SUCCESS
[Wed Aug 19 14:13:20.338140 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38416] ipa: DEBUG: Destroyed connection context.ldap2_140312891123216
[Wed Aug 19 14:13:20.340183 2020] [:warn] [pid 4210:tid 4417] [client 10.128.2.4:38416] failed to set perms (3140) on file (/run/ipa/ccaches/host~ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV)!, referer: https://ipa0.staging.cool.cyber.dhs.gov/ipa/xml
[Wed Aug 19 14:13:20.340814 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:20.340865 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Wed Aug 19 14:13:20.348807 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: Created connection context.ldap2_140312891118784
[Wed Aug 19 14:13:20.348872 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:20.348900 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:20.349107 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: raw: config_show(raw=True, version='2.0')
[Wed Aug 19 14:13:20.349211 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: config_show(rights=False, all=False, raw=True, version='2.0')
[Wed Aug 19 14:13:20.353129 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: INFO: [jsonserver_session] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: config_show(raw=True, version='2.0'): SUCCESS
[Wed Aug 19 14:13:20.353836 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38416] ipa: DEBUG: Destroyed connection context.ldap2_140312891118784
[Wed Aug 19 14:13:21.276991 2020] [:warn] [pid 4210:tid 4413] [client 10.128.2.4:38416] failed to set perms (3140) on file (/run/ipa/ccaches/host~ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV)!, referer: https://ipa0.staging.cool.cyber.dhs.gov/ipa/xml
[Wed Aug 19 14:13:21.277572 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:21.277621 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Wed Aug 19 14:13:21.285746 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: Created connection context.ldap2_140312891123072
[Wed Aug 19 14:13:21.285807 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:21.285835 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:21.286087 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: raw: host_mod('ipa2.staging.cool.cyber.dhs.gov', ipasshpubkey=('ssh-dss AAAAB3NzaC1kc3MAAACBAI6ClaOTE5/ksmqVZ1i5YQ6/g+TLS4PHqFLHNYefe7MQ19rZEdfAekQgjQe20h57HdGBlQg1eWqlPlOHmDNe5DcIKEW2nINZdf9azOJFE5eICb/U/Gi8Hf/DxGaJQzVHhXXr8fhgQ3ZckKG7XnrZQ3JauWl5lRtFPVpZ6IVvK51NAAAAFQCIgZjvRj3Ua1zIUrfmZo8hJpRD6wAAAIBfac/8P3MDIqTbIZ5l60mIvoEEvZdcnvysLorLM0Z49h3PMmX/ZsQh/LMN5vSheZhj2s9aKDz8FjrTSiIEJBRS1e7vaOHyv6XAA/udimIdUHslWeroC9xzADr2k15Nn4WUyvL1j6LzMcMrbJlpUoSGzkEmJLLUnh7xi5FoSQ8krgAAAIBGYKgh3kLosmAgGLdR9S7UhJuIaMjhf5Bu//Nr9MgMPDvuWCT6bJKJefA1l5OTkHe8EsPpm4aq4h9O2LuQm3JC5VTTc/zyGh+/TclgHmW093fAVW6ZtUvb0/jw5RO8ZycV3ETqO0GLocFFOlhyjajM1i4vyjp5ePIvZWWwlwamdg== root@ip-10-128-2-4.ec2.internal', 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDrXizpbsyXOlCFGp5ai6uSYNPpI+bApbVsBsU42QWaafrcFDNQvcViLOYUEf9eI3kdW4dw+cIbzV5ibpdZgIG0+zvvPnNq0qD9KxQ2g7dUZwWYuZeDm6umF2dlp2q1SuAn42hfwmn/CTqs2dL+1keikv3aF1SEYjC1YRrPPcXR24XdnWEwuKYjMA6+wdWZR0xX2YI39OUkNWJ3yNRqDr9E/p3irEhxzlBLxGS4NU8F/AV4khAth9JwrHNatn9Map0lXLqc6+qpAjOgxMBhvKiXF3rxI/C9L4Jm4V5Gpb57ftYX2nyGrQgVIxOxcKIApBXpXBU5xSQZ3ojx0CGVhAGKfGxfEkWfO5SsapzVzvMpedOEXf3B1TSDxER1tuOWPpt6EX3WmYcOkij4E+ZWtMrDI6taN98/TjhWU7bpnMThLji0rVvBmsdUJ8VOsWwP2jB3S/Jk10IJ86C1W+whNm8GgRkp4qzZCJHF9zhlbPv0EqYoEva9qJujnPvZ6VT27YU= root@ip-10-128-2-4.ec2.internal', 'ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBCXISbCJUxTpbiKzV+MAFn37u2U47h8vIcXxu6R/MeYlqZbO+ik8GeJiAdYi/K1GB+njxG3WO9/UNcHytIbpULY= root@ip-10-128-2-4.ec2.internal', 'ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICUNMODAA8ryT2zlnbjro+JpgfVxQC4PLXwIUeWQsS81 root@ip-10-128-2-4.ec2.internal'), updatedns=False, version='2.26')
[Wed Aug 19 14:13:21.286644 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: host_mod('ipa2.staging.cool.cyber.dhs.gov', random=False, ipasshpubkey=('ssh-dss AAAAB3NzaC1kc3MAAACBAI6ClaOTE5/ksmqVZ1i5YQ6/g+TLS4PHqFLHNYefe7MQ19rZEdfAekQgjQe20h57HdGBlQg1eWqlPlOHmDNe5DcIKEW2nINZdf9azOJFE5eICb/U/Gi8Hf/DxGaJQzVHhXXr8fhgQ3ZckKG7XnrZQ3JauWl5lRtFPVpZ6IVvK51NAAAAFQCIgZjvRj3Ua1zIUrfmZo8hJpRD6wAAAIBfac/8P3MDIqTbIZ5l60mIvoEEvZdcnvysLorLM0Z49h3PMmX/ZsQh/LMN5vSheZhj2s9aKDz8FjrTSiIEJBRS1e7vaOHyv6XAA/udimIdUHslWeroC9xzADr2k15Nn4WUyvL1j6LzMcMrbJlpUoSGzkEmJLLUnh7xi5FoSQ8krgAAAIBGYKgh3kLosmAgGLdR9S7UhJuIaMjhf5Bu//Nr9MgMPDvuWCT6bJKJefA1l5OTkHe8EsPpm4aq4h9O2LuQm3JC5VTTc/zyGh+/TclgHmW093fAVW6ZtUvb0/jw5RO8ZycV3ETqO0GLocFFOlhyjajM1i4vyjp5ePIvZWWwlwamdg== root@ip-10-128-2-4.ec2.internal', 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDrXizpbsyXOlCFGp5ai6uSYNPpI+bApbVsBsU42QWaafrcFDNQvcViLOYUEf9eI3kdW4dw+cIbzV5ibpdZgIG0+zvvPnNq0qD9KxQ2g7dUZwWYuZeDm6umF2dlp2q1SuAn42hfwmn/CTqs2dL+1keikv3aF1SEYjC1YRrPPcXR24XdnWEwuKYjMA6+wdWZR0xX2YI39OUkNWJ3yNRqDr9E/p3irEhxzlBLxGS4NU8F/AV4khAth9JwrHNatn9Map0lXLqc6+qpAjOgxMBhvKiXF3rxI/C9L4Jm4V5Gpb57ftYX2nyGrQgVIxOxcKIApBXpXBU5xSQZ3ojx0CGVhAGKfGxfEkWfO5SsapzVzvMpedOEXf3B1TSDxER1tuOWPpt6EX3WmYcOkij4E+ZWtMrDI6taN98/TjhWU7bpnMThLji0rVvBmsdUJ8VOsWwP2jB3S/Jk10IJ86C1W+whNm8GgRkp4qzZCJHF9zhlbPv0EqYoEva9qJujnPvZ6VT27YU= root@ip-10-128-2-4.ec2.internal', 'ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBCXISbCJUxTpbiKzV+MAFn37u2U47h8vIcXxu6R/MeYlqZbO+ik8GeJiAdYi/K1GB+njxG3WO9/UNcHytIbpULY= root@ip-10-128-2-4.ec2.internal', 'ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICUNMODAA8ryT2zlnbjro+JpgfVxQC4PLXwIUeWQsS81 root@ip-10-128-2-4.ec2.internal'), rights=False, updatedns=False, all=False, raw=False, version='2.26', no_members=False)
[Wed Aug 19 14:13:21.290207 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: raw: ca_is_enabled(version='2.239')
[Wed Aug 19 14:13:21.290286 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: ca_is_enabled(version='2.239')
[Wed Aug 19 14:13:21.304494 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: INFO: [jsonserver_session] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: host_mod('ipa2.staging.cool.cyber.dhs.gov', ipasshpubkey=('ssh-dss AAAAB3NzaC1kc3MAAACBAI6ClaOTE5/ksmqVZ1i5YQ6/g+TLS4PHqFLHNYefe7MQ19rZEdfAekQgjQe20h57HdGBlQg1eWqlPlOHmDNe5DcIKEW2nINZdf9azOJFE5eICb/U/Gi8Hf/DxGaJQzVHhXXr8fhgQ3ZckKG7XnrZQ3JauWl5lRtFPVpZ6IVvK51NAAAAFQCIgZjvRj3Ua1zIUrfmZo8hJpRD6wAAAIBfac/8P3MDIqTbIZ5l60mIvoEEvZdcnvysLorLM0Z49h3PMmX/ZsQh/LMN5vSheZhj2s9aKDz8FjrTSiIEJBRS1e7vaOHyv6XAA/udimIdUHslWeroC9xzADr2k15Nn4WUyvL1j6LzMcMrbJlpUoSGzkEmJLLUnh7xi5FoSQ8krgAAAIBGYKgh3kLosmAgGLdR9S7UhJuIaMjhf5Bu//Nr9MgMPDvuWCT6bJKJefA1l5OTkHe8EsPpm4aq4h9O2LuQm3JC5VTTc/zyGh+/TclgHmW093fAVW6ZtUvb0/jw5RO8ZycV3ETqO0GLocFFOlhyjajM1i4vyjp5ePIvZWWwlwamdg== root@ip-10-128-2-4.ec2.internal', 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDrXizpbsyXOlCFGp5ai6uSYNPpI+bApbVsBsU42QWaafrcFDNQvcViLOYUEf9eI3kdW4dw+cIbzV5ibpdZgIG0+zvvPnNq0qD9KxQ2g7dUZwWYuZeDm6umF2dlp2q1SuAn42hfwmn/CTqs2dL+1keikv3aF1SEYjC1YRrPPcXR24XdnWEwuKYjMA6+wdWZR0xX2YI39OUkNWJ3yNRqDr9E/p3irEhxzlBLxGS4NU8F/AV4khAth9JwrHNatn9Map0lXLqc6+qpAjOgxMBhvKiXF3rxI/C9L4Jm4V5Gpb57ftYX2nyGrQgVIxOxcKIApBXpXBU5xSQZ3ojx0CGVhAGKfGxfEkWfO5SsapzVzvMpedOEXf3B1TSDxER1tuOWPpt6EX3WmYcOkij4E+ZWtMrDI6taN98/TjhWU7bpnMThLji0rVvBmsdUJ8VOsWwP2jB3S/Jk10IJ86C1W+whNm8GgRkp4qzZCJHF9zhlbPv0EqYoEva9qJujnPvZ6VT27YU= root@ip-10-128-2-4.ec2.internal', 'ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBCXISbCJUxTpbiKzV+MAFn37u2U47h8vIcXxu6R/MeYlqZbO+ik8GeJiAdYi/K1GB+njxG3WO9/UNcHytIbpULY= root@ip-10-128-2-4.ec2.internal', 'ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAICUNMODAA8ryT2zlnbjro+JpgfVxQC4PLXwIUeWQsS81 root@ip-10-128-2-4.ec2.internal'), updatedns=False, version='2.26'): SUCCESS
[Wed Aug 19 14:13:21.305093 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38416] ipa: DEBUG: Destroyed connection context.ldap2_140312891123072
[Wed Aug 19 14:13:27.626273 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:27.626326 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:27.626354 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Wed Aug 19 14:13:27.637341 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: Created connection context.ldap2_140312891118928
[Wed Aug 19 14:13:27.637396 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:27.637779 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: raw: env(('version',), version='2.239')
[Wed Aug 19 14:13:27.637884 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: env(('version',), server=False, all=True, version='2.239')
[Wed Aug 19 14:13:27.638020 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: INFO: [jsonserver_kerb] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: env(('version',)): SUCCESS
[Wed Aug 19 14:13:27.638534 2020] [wsgi:error] [pid 4207:tid 4469] [remote 10.128.2.4:38450] ipa: DEBUG: Destroyed connection context.ldap2_140312891118928
[Wed Aug 19 14:13:27.648886 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:27.648939 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:27.648967 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Wed Aug 19 14:13:27.659625 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: Created connection context.ldap2_140312891123216
[Wed Aug 19 14:13:27.659682 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:27.660111 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: raw: env(('fips_mode',), version='2.239')
[Wed Aug 19 14:13:27.660213 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: env(('fips_mode',), server=False, all=True, version='2.239')
[Wed Aug 19 14:13:27.660588 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: INFO: [jsonserver_kerb] host/ipa2.staging.cool.cyber.dhs.gov@STAGING.COOL.CYBER.DHS.GOV: env(('fips_mode',)): SUCCESS
[Wed Aug 19 14:13:27.661123 2020] [wsgi:error] [pid 4205:tid 4472] [remote 10.128.2.4:38450] ipa: DEBUG: Destroyed connection context.ldap2_140312891123216
[Wed Aug 19 14:13:30.577499 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:30.577548 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:30.577577 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Wed Aug 19 14:13:30.589011 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: Created connection context.ldap2_140312891118784
[Wed Aug 19 14:13:30.589063 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:30.589263 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: raw: ping(version='2.239')
[Wed Aug 19 14:13:30.589329 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: ping(version='2.239')
[Wed Aug 19 14:13:30.589420 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: INFO: [jsonserver_kerb] jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV: ping/1(version='2.239'): SUCCESS
[Wed Aug 19 14:13:30.589904 2020] [wsgi:error] [pid 4204:tid 4475] [remote 10.128.2.4:38480] ipa: DEBUG: Destroyed connection context.ldap2_140312891118784
[Wed Aug 19 14:13:30.729624 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Wed Aug 19 14:13:30.729676 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: WSGI jsonserver.__call__:
[Wed Aug 19 14:13:30.729726 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Wed Aug 19 14:13:30.747801 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: Created connection context.ldap2_140312891123072
[Wed Aug 19 14:13:30.747864 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Wed Aug 19 14:13:30.748183 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: raw: server_conncheck('ipa0.staging.cool.cyber.dhs.gov', 'ipa2.staging.cool.cyber.dhs.gov', version='2.162')
[Wed Aug 19 14:13:30.748264 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: server_conncheck('ipa0.staging.cool.cyber.dhs.gov', 'ipa2.staging.cool.cyber.dhs.gov', version='2.162')
[Wed Aug 19 14:13:55.787358 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: ERROR: non-public: DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
[Wed Aug 19 14:13:55.787389 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] Traceback (most recent call last):
[Wed Aug 19 14:13:55.787393 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipaserver/rpcserver.py", line 395, in wsgi_execute
[Wed Aug 19 14:13:55.787397 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     result = command(*args, **options)
[Wed Aug 19 14:13:55.787400 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 450, in __call__
[Wed Aug 19 14:13:55.787403 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self.__do_call(*args, **options)
[Wed Aug 19 14:13:55.787407 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 478, in __do_call
[Wed Aug 19 14:13:55.787410 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     ret = self.run(*args, **options)
[Wed Aug 19 14:13:55.787413 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 800, in run
[Wed Aug 19 14:13:55.787416 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self.execute(*args, **options)
[Wed Aug 19 14:13:55.787419 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipaserver/plugins/server.py", line 935, in execute
[Wed Aug 19 14:13:55.787423 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     ret, stdout, _stderr = server.conncheck(keys[-1])
[Wed Aug 19 14:13:55.787426 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib64/python3.8/site-packages/dbus/proxies.py", line 72, in __call__
[Wed Aug 19 14:13:55.787429 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self._proxy_method(*args, **keywords)
[Wed Aug 19 14:13:55.787432 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib64/python3.8/site-packages/dbus/proxies.py", line 141, in __call__
[Wed Aug 19 14:13:55.787450 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self._connection.call_blocking(self._named_service,
[Wed Aug 19 14:13:55.787453 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib64/python3.8/site-packages/dbus/connection.py", line 652, in call_blocking
[Wed Aug 19 14:13:55.787456 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     reply_message = self.send_message_with_reply_and_block(
[Wed Aug 19 14:13:55.787460 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
[Wed Aug 19 14:13:55.787761 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: INFO: [jsonserver_kerb] jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV: server_conncheck('ipa0.staging.cool.cyber.dhs.gov', 'ipa2.staging.cool.cyber.dhs.gov', version='2.162'): InternalError
[Wed Aug 19 14:13:55.788325 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: DEBUG: Destroyed connection context.ldap2_140312891123072

I'm guessing the DBUS error is the culprit? My /etc/sssd/sssd.conf looks like this:

[domain/staging.cool.cyber.dhs.gov]
debug_level = 9
id_provider = ipa
ipa_server = ipa0.staging.cool.cyber.dhs.gov
ipa_domain = staging.cool.cyber.dhs.gov
ipa_hostname = ipa0.staging.cool.cyber.dhs.gov
auth_provider = ipa
chpass_provider = ipa
access_provider = ipa
cache_credentials = True
ldap_tls_cacert = /etc/ipa/ca.crt
krb5_store_password_if_offline = True
sudo_provider = ipa
autofs_provider = ipa
subdomains_provider = ipa
session_provider = ipa
hostid_provider = ipa
ipa_server_mode = True
[sssd]
services = nss, pam, ssh, sudo, ifp
domains = staging.cool.cyber.dhs.gov
[nss]
homedir_substring = /home
[pam]
[sudo]
[autofs]
[ssh]
[pac]
[ifp]
allowed_uids = ipaapi, root
[secrets]
[session_recording]

Note that the sssd.conf file allows ipaapi under ifp. I have been adding this as part of my FreeiPA installation while waiting for the fix from issue #8403 to make its way into the Fedora upstream.
Edited by jsf9k

@frenaud, I'm guessing the problem is this:

ipa: ERROR: non-public: DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
[Wed Aug 19 14:13:55.787389 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] Traceback (most recent call last):
[Wed Aug 19 14:13:55.787393 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipaserver/rpcserver.py", line 395, in wsgi_execute
[Wed Aug 19 14:13:55.787397 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     result = command(*args, **options)
[Wed Aug 19 14:13:55.787400 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 450, in __call__
[Wed Aug 19 14:13:55.787403 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self.__do_call(*args, **options)
[Wed Aug 19 14:13:55.787407 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 478, in __do_call
[Wed Aug 19 14:13:55.787410 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     ret = self.run(*args, **options)
[Wed Aug 19 14:13:55.787413 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 800, in run
[Wed Aug 19 14:13:55.787416 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self.execute(*args, **options)
[Wed Aug 19 14:13:55.787419 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib/python3.8/site-packages/ipaserver/plugins/server.py", line 935, in execute
[Wed Aug 19 14:13:55.787423 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     ret, stdout, _stderr = server.conncheck(keys[-1])
[Wed Aug 19 14:13:55.787426 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib64/python3.8/site-packages/dbus/proxies.py", line 72, in __call__
[Wed Aug 19 14:13:55.787429 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self._proxy_method(*args, **keywords)
[Wed Aug 19 14:13:55.787432 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib64/python3.8/site-packages/dbus/proxies.py", line 141, in __call__
[Wed Aug 19 14:13:55.787450 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     return self._connection.call_blocking(self._named_service,
[Wed Aug 19 14:13:55.787453 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]   File "/usr/lib64/python3.8/site-packages/dbus/connection.py", line 652, in call_blocking
[Wed Aug 19 14:13:55.787456 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480]     reply_message = self.send_message_with_reply_and_block(
[Wed Aug 19 14:13:55.787460 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
[Wed Aug 19 14:13:55.787761 2020] [wsgi:error] [pid 4206:tid 4466] [remote 10.128.2.4:38480] ipa: INFO: [jsonserver_kerb] jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV: server_conncheck('ipa0.staging.cool.cyber.dhs.gov', 'ipa2.staging.cool.cyber.dhs.gov', version='2.162'): InternalError

Unfortunately i'm too ignorant of FreeIPA to know where to proceed from here. Can you try to get me pointed in the right direction? Thank you!

This calls out to oddjob via dbus to do the connection check. Is oddjob running?

Oddjob is definitely running. I believe that comes along for free as part of the FreeIPA install.

The original error indicates that the new machine can talk to the existing IPA server fine but the reverse is not true. Have you ruled out firewalls and such?

I'm not sure how to debug this dbus issue. Perhaps try dbus-monitor to see if that shows anything useful.

I don't think there is any firewall in the way. Any such firewall should be unchanged from when this used to work.

I have some other, more pressing work right now but I will come back to this.

I apologize for the long delay. I was assigned another high-priority task that completely consumed me for the past month. Now I am back to debugging this issue.

You might recall that the main issue is that, when I create a replica, the connection check from client to master passes but the check from master to client fails. I dug into the source code a little more, and I can see from this bit of code that when the connection check happens the client runs this command:

/usr/sbin/ipa-replica-conncheck --debug --master ipa0.staging.cool.cyber.dhs.gov --auto-master-check --realm STAGING.COOL.CYBER.DHS.GOV --hostname ipa1.staging.cool.cyber.dhs.gov --ca-cert-file /etc/ipa/ca.crt

(I added the --debug in case it gave me some extra information that would help.)

I ran that command a few times on the client, looking for some corresponding log output on the server. I found this in /var/log/httpd/error_log:

[Tue Sep 22 20:50:47.132117 2020] [:warn] [pid 189783:tid 189828] [client 10.128.1.4:37856] failed to set perms (3140) on file (/run/ipa/ccaches/jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV)!, referer: https://ipa0.staging.cool.cyber.dhs.gov/ipa/xml
[Tue Sep 22 20:50:47.140507 2020] [wsgi:error] [pid 185212:tid 185482] [remote 10.128.1.4:37856] ipa: INFO: [jsonserver_session] jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV: ping/1(version='2.239'): SUCCESS
[Tue Sep 22 20:50:47.143312 2020] [:warn] [pid 189783:tid 189824] [client 10.128.1.4:37856] failed to set perms (3140) on file (/run/ipa/ccaches/jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV)!, referer: https://ipa0.staging.cool.cyber.dhs.gov/ipa/xml
[Tue Sep 22 20:50:47.161053 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856] ipa: ERROR: non-public: RuntimeError: To make asynchronous calls, receive signals or export objects, D-Bus connections must be attached to a main loop by passing mainloop=... to the constructor or calling dbus.set_default_main_loop(...)
[Tue Sep 22 20:50:47.161155 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856] Traceback (most recent call last):
[Tue Sep 22 20:50:47.161192 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]   File "/usr/lib/python3.8/site-packages/ipaserver/rpcserver.py", line 395, in wsgi_execute
[Tue Sep 22 20:50:47.161211 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]     result = command(*args, **options)
[Tue Sep 22 20:50:47.161236 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 471, in __call__
[Tue Sep 22 20:50:47.161257 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]     return self.__do_call(*args, **options)
[Tue Sep 22 20:50:47.161278 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 499, in __do_call
[Tue Sep 22 20:50:47.161300 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]     ret = self.run(*args, **options)
[Tue Sep 22 20:50:47.161321 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]   File "/usr/lib/python3.8/site-packages/ipalib/frontend.py", line 821, in run
[Tue Sep 22 20:50:47.161349 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]     return self.execute(*args, **options)
[Tue Sep 22 20:50:47.161367 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]   File "/usr/lib/python3.8/site-packages/ipaserver/plugins/server.py", line 931, in execute
[Tue Sep 22 20:50:47.161388 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]     obj = bus.get_object('org.freeipa.server', '/',
[Tue Sep 22 20:50:47.161410 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]   File "/usr/lib64/python3.8/site-packages/dbus/bus.py", line 225, in get_object
[Tue Sep 22 20:50:47.161429 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856]     self._require_main_loop()   # we don't get the signals otherwise
[Tue Sep 22 20:50:47.161451 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856] RuntimeError: To make asynchronous calls, receive signals or export objects, D-Bus connections must be attached to a main loop by passing mainloop=... to the constructor or calling dbus.set_default_main_loop(...)
[Tue Sep 22 20:50:47.162094 2020] [wsgi:error] [pid 185210:tid 185473] [remote 10.128.1.4:37856] ipa: INFO: [jsonserver_session] jeremy.frasier@STAGING.COOL.CYBER.DHS.GOV: server_conncheck('ipa0.staging.cool.cyber.dhs.gov', 'ipa1.staging.cool.cyber.dhs.gov', version='2.162'): InternalError

It looks like the problem is indeed related to D-BUS/oddjobd as @rcritten suspected, but I don't know how to proceed from here. Does this To make asynchronous calls, receive signals or export objects, D-Bus connections must be attached to a main loop error ring a bell with anyone? If not, does anyone have any thoughts as to how I can trace this further?

Something about dbus seems to be broken. The loop is set two lines above where the error is occurring:

dbus.mainloop.glib.DBusGMainLoop(set_as_default=True)

So I think the system bus is hosed in some way on this machine. Are you seeing this happen anywhere else?

rpm -V on the dbus-related packages might be useful in case something has been modified.

Hmmm...I think the rpms are ok:

[jeremy.frasier@ipa1 log]$ sudo rpm -V dbus dbus-broker dbus-common dbus-libs dbus-tools 
[jeremy.frasier@ipa1 log]$ echo $?
0
[jeremy.frasier@ipa1 log]$ sudo yum install dbus dbus-broker dbus-common dbus-libs dbus-tools 
Last metadata expiration check: 2:37:02 ago on Wed 23 Sep 2020 05:56:16 PM UTC.
Package dbus-1:1.12.20-1.fc32.x86_64 is already installed.
Package dbus-broker-24-1.fc32.x86_64 is already installed.
Package dbus-common-1:1.12.20-1.fc32.noarch is already installed.
Package dbus-libs-1:1.12.20-1.fc32.x86_64 is already installed.
Package dbus-tools-1:1.12.20-1.fc32.x86_64 is already installed.
Dependencies resolved.
Nothing to do.
Complete!

Maybe try a basic dbus command to directly test the bus:

# dbus-send --system --dest=org.fedorahosted.certmonger \
--type=method_call --print-reply \
/org/fedorahosted/certmonger \
org.fedorahosted.certmonger.get_requests

With no tracked requests (I assume) you should get something like:

method return time=1600951278.292812 sender=:1.139701 -> destination=:1.139700 serial=5 reply_serial=2
array [
]

On the master I get this:

[jeremy.frasier@ipa0 ~]$ dbus-send --system --dest=org.fedorahosted.certmonger \
> --type=method_call --print-reply \
> /org/fedorahosted/certmonger \
> org.fedorahosted.certmonger.get_requests
Error org.freedesktop.DBus.Error.AccessDenied: Sender is not authorized to send message
[jeremy.frasier@ipa0 ~]$ sudo dbus-send --system --dest=org.fedorahosted.certmonger --type=method_call --print-reply /org/fedorahosted/certmonger org.fedorahosted.certmonger.get_requests
method return time=1600978652.314609 sender=:1.20 -> destination=:1.10003 serial=946 reply_serial=2
   array [
      object path "/org/fedorahosted/certmonger/requests/Request1"
      object path "/org/fedorahosted/certmonger/requests/Request2"
      object path "/org/fedorahosted/certmonger/requests/Request3"
      object path "/org/fedorahosted/certmonger/requests/Request4"
      object path "/org/fedorahosted/certmonger/requests/Request5"
      object path "/org/fedorahosted/certmonger/requests/Request6"
      object path "/org/fedorahosted/certmonger/requests/Request7"
      object path "/org/fedorahosted/certmonger/requests/Request8"
      object path "/org/fedorahosted/certmonger/requests/Request9"
      object path "/org/fedorahosted/certmonger/requests/Request10"
      object path "/org/fedorahosted/certmonger/requests/Request11"
      object path "/org/fedorahosted/certmonger/requests/Request12"
   ]

Note that I have to run via sudo to get anything.

@rcritten, I also tried running the command as the ipaapi user:

[jeremy.frasier@ipa0 ~]$ sudo -u ipaapi dbus-send --system --dest=org.fedorahosted.certmonger --type=method_call --print-reply /org/fedorahosted/certmonger org.fedorahosted.certmonger.get_requests
Error org.freedesktop.DBus.Error.AccessDenied: Sender is not authorized to send message

Is this a problem? Here are the contents of my /etc/sssd file:

[jeremy.frasier@ipa0 ~]$ sudo less /etc/sssd/sssd.conf
[domain/staging.cool.cyber.dhs.gov]
id_provider = ipa
ipa_server_mode = True
ipa_server = ipa0.staging.cool.cyber.dhs.gov
ipa_domain = staging.cool.cyber.dhs.gov
ipa_hostname = ipa0.staging.cool.cyber.dhs.gov
auth_provider = ipa
chpass_provider = ipa
access_provider = ipa
cache_credentials = True
ldap_tls_cacert = /etc/ipa/ca.crt
krb5_store_password_if_offline = True
[sssd]
services = nss, pam, ifp, ssh, sudo
domains = staging.cool.cyber.dhs.gov
[nss]
homedir_substring = /home
memcache_timeout = 600
[pam]
[sudo]
[autofs]
[ssh]
[pac]
[ifp]
allowed_uids = ipaapi, root
[secrets]
[session_recording]
Edited by jsf9k

IPA uses oddjob to make the request when in the wsgi.

During the installation the user is root.

Does dbus work on the replica you are trying to install?

I have found that this problem continues to happen, but I found a workaround. If server X tries to establish itself as a replica by replicating against server Y, and I see this issue, then a systemctl restart ipa.service on server Y seems to make everything work again.

I wish I could figure out exactly what is failing to cause this, and why, but so far I have not been able to. Feel free to close this ticket for now if you want.

Failure observed in testing_master_previous PR 997 Report

@sumedhs The failure from testing_master_previous PR 997 rather looks like #8870 Multiple nightly test failures with "Custodia uses 'master.ipa.test' as master peer" and "DBusException".

Closing this ticket as agreed with jsf9k since we don't manage to reproduce.

Metadata Update from @frenaud:
- Issue close_status updated to: worksforme
- Issue status updated to: Closed (was: Open)
Metadata
None
None
None
None
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.