Bug 1879604

this is due to:
https://github.com/dogtagpki/pki/commit/0102d836f4eac0fcea0adddb4c98d5ea05e4e8f6
and can be worked around on ipa side by adding --debug to the pkispawn invocation.

Upstream issue: https://pagure.io/freeipa/issue/8503
PR: https://github.com/freeipa/freeipa/pull/5113

Logs showing the issue (the file only contains the gzip headers): http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/ae7eb046-f838-11ea-8647-fa163e5fd761/test_integration-test_replica_promotion.py-TestSubCAkeyReplication-test_subca_replica/master.ipa.test/var/log/pki/

Proper log with --debug invocation: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/7465d796-f83c-11ea-ae35-fa163e43b58c/test_integration-test_external_ca.py-TestExternalCAProfileScenarios-test_valid_v1_template/master.ipa.test/var/log/pki/

Move to assigned state, based on the upstream PR work.

Upstream PR:
https://github.com/freeipa/freeipa/pull/5113
is approved and running through upstream gating.

It has upstream test coverage:

Expected failure without the fix: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/f2117a58-f871-11ea-9e9e-fa163e2dc507/report.html

self = <ipatests.test_integration.test_commands.TestIPACommand object at 0x7fdcb353db20>

    def test_pkispawn_log_is_present(self):
        """
        This testcase checks if pkispawn logged properly.
        It is a candidate from being moved out of test_commands.
        """
        result = self.master.run_command(
            ["ls", "/var/log/pki/"]
        )
        pkispawnlogfile = None
        for file in result.stdout_text.splitlines():
            if file.startswith("pki-ca-spawn"):
                pkispawnlogfile = file
                break
        assert pkispawnlogfile is not None
        pkispawnlogfile = os.path.sep.join(("/var/log/pki", pkispawnlogfile))
        pkispawnlog = self.master.get_file_contents(
            pkispawnlogfile, encoding='utf-8'
        )
        # Totally arbitrary. pkispawn debug logs tend to be > 10KiB.
>       assert len(pkispawnlog) > 1024
E       AssertionError: assert 0 > 1024
E        +  where 0 = len('')

test_integration/test_commands.py:1318: AssertionError
 -------------------------------Captured log call-------------------------------- 
INFO     ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport:transport.py:391 RUN ['ls', '/var/log/pki/']
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd430:transport.py:513 RUN ['ls', '/var/log/pki/']
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd430:transport.py:557 pki-ca-spawn.20200916231608.log
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd430:transport.py:557 pki-tomcat
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd430:transport.py:217 Exit code: 0
INFO     ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport:transport.py:436 GET /var/log/pki/pki-ca-spawn.20200916231608.log
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd431:transport.py:513 RUN ['cat', '/var/log/pki/pki-ca-spawn.20200916231608.log']
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd431:transport.py:217 Exit code: 0


Green run with the fix: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/cf98f4e8-f8b1-11ea-8724-fa163e54c0e1/report.html

Fixed upstream
master:
https://pagure.io/freeipa/c/c31bf3d430763ef5b0ef28510995af48dccde287
https://pagure.io/freeipa/c/be7bf98b3b8cb1db9d4baa5548991ac72049ade8

Fixed upstream
ipa-4-8:
https://pagure.io/freeipa/c/d1c860e59b5237178066ed963cc2fa50d99cd690
https://pagure.io/freeipa/c/97c6d2d2c2359b8ff5585afa0d2e5f5599cd5048

Manual verification:

[root@ip test]# rpm -q ipa-server
ipa-server-4.8.7-12.module+el8.3.0+8222+c1bff54a.x86_64

[root@ip test]# cat /etc/os-release 
NAME="Red Hat Enterprise Linux"
VERSION="8.3 (Ootpa)"


[root@ip test]# ipa-server-install --domain dom-$(hostname -f) --realm DOM-$(hostname -f | tr '[:lower:]' '[:upper:]') -a ***** -p ***** -U
...output truncated...
SUCCESS

[root@ip test]# ls /var/log/pki
/var/log/pki/pki-ca-spawn.20200924124514.log  pki-tomcat


[root@ip test]# head /var/log/pki/pki-ca-spawn.20200924124514.log 
2020-09-24 12:45:14 INFO: Connecting to LDAP server at ldap://never.gonna.give.you.up:389
2020-09-24 12:45:14 INFO: Connecting to LDAP server at ldap://never.gonna.let.you.down:389
2020-09-24 12:45:14 DEBUG: Installing Maven dependencies: False
2020-09-24 12:45:14 INFO: BEGIN spawning CA subsystem in pki-tomcat instance
2020-09-24 12:45:14 INFO: Loading instance: pki-tomcat
2020-09-24 12:45:14 INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf
2020-09-24 12:45:14 INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf
2020-09-24 12:45:14 INFO: Setting up pkiuser group
2020-09-24 12:45:14 INFO: Reusing existing pkiuser group with GID n
2020-09-24 12:45:14 INFO: Setting up pkiuser user


Hereby marking as VERIFIED. Automation exists in test test_pkispawn_log_is_present added in ipatests/test_integration/test_commands.py

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: idm:DL1 and idm:client security, bug fix, and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2020:4670

The needinfo request[s] on this closed bug have been removed as they have been unresolved for 500 days