Bug 1879604 - pkispawn logs files are empty [NEEDINFO]
Summary: pkispawn logs files are empty
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: ipa
Version: 8.3
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: rc
: 8.3
Assignee: François Cami
QA Contact: ipa-qe
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-09-16 15:42 UTC by François Cami
Modified: 2021-09-03 15:25 UTC (History)
13 users (show)

Fixed In Version: ipa-4.8.7-12
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1879515
Environment:
Last Closed: 2020-11-04 02:51:33 UTC
Type: Bug
Target Upstream Version:
pm-rhel: needinfo? (twoerner)


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2020:4670 0 None None None 2020-11-04 02:51:44 UTC

Description François Cami 2020-09-16 15:42:05 UTC
+++ This bug was initially created as a clone of Bug #1879515 +++

Description of problem:
When installing a CA instance in IPA, pkispawn no longer logs installation steps and debug logs to /var/log/pki/pki-$subsystem-spawn.$date.log. The log files are empty. The debug logs are important for IPA to understand and debug installation problems.

Version-Release number of selected component (if applicable):
pki-base-10.9.3-1.module+el8.3.0+7928+ce88aa94.noarch
ipa-server-4.8.7-10.module+el8.3.0+7702+ced5f219.x86_64


How reproducible:
always

Steps to Reproduce:
1. dnf -y module enable idm:DL1
2. dnf install ipa-server
3. ipa-server-install

Actual results:
# ls -la /var/log/pki/pki-ca-spawn.20200916083742.log 
-rw-rw-r--. 1 root root 0 Sep 16 08:37 /var/log/pki/pki-ca-spawn.20200916083742.log

Expected results:
The log file contains detailed debug logging of every step.

Additional info:

Comment 1 François Cami 2020-09-16 15:44:29 UTC
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.

Comment 10 Alexander Bokovoy 2020-09-17 07:40:33 UTC
Move to assigned state, based on the upstream PR work.

Comment 11 François Cami 2020-09-17 11:49:41 UTC
Upstream PR:
https://github.com/freeipa/freeipa/pull/5113
is approved and running through upstream gating.

Comment 12 François Cami 2020-09-17 11:50:47 UTC
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

Comment 20 Michal Polovka 2020-09-24 17:07:32 UTC
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

Comment 23 errata-xmlrpc 2020-11-04 02:51:33 UTC
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


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