1643880 – PKI subsystem process is not shutdown when there is no space on the disk to write logs [rhel-7.6.z]

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1643880 - PKI subsystem process is not shutdown when there is no space on the disk to write logs [rhel-7.6.z]

Summary: PKI subsystem process is not shutdown when there is no space on the disk to w...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	pki-core
Sub Component:
Version:	7.6
Hardware:	All
OS:	Linux
Priority:	high
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	Endi Sukma Dewata
QA Contact:	Asha Akkiangady
Docs Contact:
URL:
Whiteboard:
Depends On:	1639710
Blocks:
TreeView+	depends on / blocked

Reported:	2018-10-29 10:19 UTC by Oneata Mircea Teodor
Modified:	2019-01-29 17:22 UTC (History)
CC List:	6 users (show)
Fixed In Version:	pki-core-10.5.9-7.el7_6
Doc Type:	No Doc Update
Doc Text:	undefined
Clone Of:	1639710
Environment:
Last Closed:	2019-01-29 17:21:55 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2019:0168	0	None	None	None	2019-01-29 17:22:01 UTC

Description Oneata Mircea Teodor 2018-10-29 10:19:25 UTC

This bug has been copied from bug #1639710 and has been proposed to be backported to 7.6 z-stream (EUS).

Comment 2 Matthew Harmsen 2018-10-31 05:10:42 UTC

PKI subsystem (example: CA) process is not shutdown when there is no space on the disk to write logs (example: signed audit log).

Testing CA instance when signedaudit log is full:
1. pkispawn a CA instance
2. Create a small partition on the disk.
create a 2M ram-disk for audit logs at /audit-logs:
Login as a super user
# mkdir /audit-logs
# mount -t tmpfs -o size=2M,mode=0755 tmpfs /audit-logs
# chown pkiuser:pkiuser /audit-logs
Add appropriate selinux context to the partition:
# /usr/sbin/semanage fcontext -a -t pki_tps_log_t /audit-logs
# /sbin/restorecon -vR /audit-logs

3. Configure CA signed audit true and signed audit log to write to this new partition.
Note: Save value of parameter log.instance.SignedAudit.fileName. log.instance.SignedAudit.logSigning=true log.instance.SignedAudit.fileName=/audit-logs/ca_audit

4. Restart the subsystem.
# systemctl restart pki-tomcatd@<ca-inst>.service
5.Fill the partiton:
Login to the shell as a super user, fill the new partition by creating a big file using dd command. Modify the "bs" value so that your partion is filled. example: # dd if=/dev/zero of=/audit-logs/bigfile bs=1M count=117

6. From CA agent page or using CLI commands make some more requests to CA so that the partition is completely full. Notice that it stops writing to file /audit-logs/ca_audit.

An exception indicating disk is full should be logged in Catalina log file.
Servlets should be disabled.
CA process should completely shut down.

Additional info:
Documentation for this feature: https://access.redhat.com/documentation/en-us/red_hat_certificate_system/9/html/administration_guide/java-logs
See section 15.2.5.7. Handling Audit Logging Failures

Comment 4 Asha Akkiangady 2018-11-16 17:08:56 UTC

Verified in version:
pki-server-10.5.9-7.el7_6.noarch
pki-ca-10.5.9-7.el7_6.noarch
pki-kra-10.5.9-7.el7_6.noarch
pki-ocsp-10.5.9-7.el7pki.noarch
pki-tks-10.5.9-7.el7pki.noarch
pki-tps-10.5.9-7.el7pki.x86_64

Tested CA, KRA, OCSP, TKS and TPS when audit log message can't be written, all subsystems shutdown as expected. UI and CLI requests results in http status 404.
 
Subsystem debug log shows subsystem shutdown message:

CA:

[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSStartServlet.destroy(): shutdown server
[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSEngine.shutdown()
[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapBoundConnFactory(DirAclAuthz)
[15/Nov/2018:11:44:56][LDAPConnThread-17 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: begins
[15/Nov/2018:11:44:56][LDAPConnThread-17 ldaps://XXXXXXXXXX:7636]: SignedAuditLogger: event CLIENT_ACCESS_SESSION_TERMINATED
[15/Nov/2018:11:44:56][LDAPConnThread-17 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: CS_CLIENT_ACCESS_SESSION_TERMINATED
[15/Nov/2018:11:44:56][LDAPConnThread-17 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: clientIP=XXXXXXXXXX serverIP=XXXXXXXXXX serverPort=7636 reason=CLOSE_NOTIFY
[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapAnonConnFactory(DirBasedAuthentication)
[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: disconnecting connection 0
...
[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: SignedAuditLogger: event AUDIT_LOG_SHUTDOWN
[15/Nov/2018:11:44:56][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: LogFile: event type not selected: AUDIT_LOG_SHUTDOWN

# pki -p 31080 -vv ca-cert-find
Server URI: http://XXXXXXXXXX:31080
Client security database: /root/.dogtag/nssdb
Message format: null
Command: ca-cert-find
Initializing security database
Module: ca
Module: cert
Module: find
Initializing PKIClient
HTTP request: GET /pki/rest/info HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:31080
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Set-Cookie: JSESSIONID=7DA6110B1160A85251D501374F338D15; Path=/pki; HttpOnly
  Content-Type: application/xml
  Content-Length: 106
  Date: Thu, 15 Nov 2018 17:54:12 GMT
HTTP request: POST /ca/rest/certs/search HTTP/1.1
  Content-Type: application/xml
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Content-Length: 594
  Host: XXXXXXXXXX:31080
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 404 Not Found
  Server: Apache-Coyote/1.1
  Content-Type: text/html;charset=utf-8
  Content-Language: en
  Content-Length: 991
  Date: Thu, 15 Nov 2018 17:54:12 GMT
com.netscape.certsrv.base.PKIException: Not Found
	at com.netscape.certsrv.client.PKIConnection.handleErrorResponse(PKIConnection.java:467)
	at com.netscape.certsrv.client.PKIConnection.getEntity(PKIConnection.java:439)
	at com.netscape.certsrv.client.PKIClient.getEntity(PKIClient.java:107)
	at com.netscape.certsrv.ca.CACertClient.findCerts(CACertClient.java:82)
	at com.netscape.cmstools.cert.CertFindCLI.execute(CertFindCLI.java:250)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:67)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:630)
	at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:666)

===================================================
KRA:

[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSStartServlet.destroy(): shutdown server
[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSEngine.shutdown()
[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapBoundConnFactory(DirAclAuthz)
[15/Nov/2018:15:26:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: begins
[15/Nov/2018:15:26:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: SignedAuditLogger: event CLIENT_ACCESS_SESSION_TERMINATED
[15/Nov/2018:15:26:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: CS_CLIENT_ACCESS_SESSION_TERMINATED
[15/Nov/2018:15:26:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: clientIP=XXXXXXXXXX serverIP=XXXXXXXXXX serverPort=7636 reason=CLOSE_NOTIFY
[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapAnonConnFactory(PasswdUserDBAuthentication)
[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: disconnecting connection 0
...
[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: SignedAuditLogger: event AUDIT_LOG_SHUTDOWN
[15/Nov/2018:15:26:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: LogFile: event type not selected: AUDIT_LOG_SHUTDOWN

# pki -v -d /root/.dogtag/rhqa_pki/certs_db -n "PKI KRA Administrator for Non-TMS-KRA" -c SECret.123 -h `hostname` -p 28044 kra-user-add --fullName="KRA AdminValid" KRAadminV
PKI options: -v -d /root/.dogtag/rhqa_pki/certs_db
PKI command: PKI KRA Administrator for Non-TMS-KRA -n PKI KRA Administrator for Non-TMS-KRA -c SECret.123 -h XXXXXXXXXX -p 28044 kra-user-add --fullName=KRA AdminValid KRAadminV
Java command: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java -Djava.ext.dirs=/usr/share/pki/lib -Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties com.netscape.cmstools.cli.MainCLI -d /root/.dogtag/rhqa_pki/certs_db --verbose -n PKI KRA Administrator for Non-TMS-KRA -c SECret.123 -h XXXXXXXXXX -p 28044 kra-user-add --fullName=KRA AdminValid KRAadminV
Server URI: http://XXXXXXXXXX:28044
Client security database: /root/.dogtag/rhqa_pki/certs_db
Message format: null
Command: kra-user-add "--fullName=KRA AdminValid" KRAadminV
Initializing security database
Getting internal token
Logging into NSS FIPS 140-2 User Private Key
Module: kra
Initializing PKIClient
HTTP request: GET /pki/rest/info HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:28044
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Set-Cookie: JSESSIONID=410727002C82A3407035C7960A965BA8; Path=/pki; HttpOnly
  Content-Type: application/xml
  Content-Length: 106
  Date: Thu, 15 Nov 2018 20:34:12 GMT
HTTP request: GET /pki/rest/info HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:28044
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
  Cookie: JSESSIONID=410727002C82A3407035C7960A965BA8
  Cookie2: $Version=1
HTTP response: HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Content-Type: application/xml
  Content-Length: 106
  Date: Thu, 15 Nov 2018 20:34:12 GMT
HTTP request: GET /kra/rest/account/login HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:28044
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 404 Not Found
  Server: Apache-Coyote/1.1
  Content-Type: text/html;charset=utf-8
  Content-Language: en
  Content-Length: 995
  Date: Thu, 15 Nov 2018 20:34:12 GMT
com.netscape.certsrv.base.PKIException: Not Found
	at com.netscape.certsrv.client.PKIConnection.handleErrorResponse(PKIConnection.java:467)
	at com.netscape.certsrv.client.PKIConnection.getEntity(PKIConnection.java:439)
	at com.netscape.certsrv.client.PKIClient.getEntity(PKIClient.java:107)
	at com.netscape.certsrv.account.AccountClient.login(AccountClient.java:46)
	at com.netscape.certsrv.client.SubsystemClient.login(SubsystemClient.java:47)
	at com.netscape.cmstools.cli.SubsystemCLI.login(SubsystemCLI.java:46)
	at com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:64)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:630)
	at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:666)
ERROR: Command '['/usr/lib/jvm/jre-1.8.0-openjdk/bin/java', '-Djava.ext.dirs=/usr/share/pki/lib', '-Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties', 'com.netscape.cmstools.cli.MainCLI', '-d', '/root/.dogtag/rhqa_pki/certs_db', '--verbose', '-n', 'PKI KRA Administrator for Non-TMS-KRA', '-c', 'SECret.123', '-h', 'XXXXXXXXXX', '-p', '28044', 'kra-user-add', '--fullName=KRA AdminValid', 'KRAadminV']' returned non-zero exit status 255

==================================================
OCSP:

[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSStartServlet.destroy(): shutdown server
[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSEngine.shutdown()
[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapBoundConnFactory(DirAclAuthz)
[15/Nov/2018:15:52:22][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: begins
[15/Nov/2018:15:52:22][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: SignedAuditLogger: event CLIENT_ACCESS_SESSION_TERMINATED
[15/Nov/2018:15:52:22][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: CS_CLIENT_ACCESS_SESSION_TERMINATED
[15/Nov/2018:15:52:22][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: clientIP=XXXXXXXXXX serverIP=XXXXXXXXXX serverPort=7636 reason=CLOSE_NOTIFY
[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapAnonConnFactory(PasswdUserDBAuthentication)
[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: disconnecting connection 0
...
[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: SignedAuditLogger: event AUDIT_LOG_SHUTDOWN
[15/Nov/2018:15:52:22][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: LogFile: event type not selected: AUDIT_LOG_SHUTDOWN

# pki -v -d /root/.dogtag/rhqa_pki/certs_db -n "PKI OCSP Administrator for Non-TMS-OCSP" -c SECret.123 -h `hostname` -p 32044 ocsp-user-add --fullName="OCSP AdminValid2" OCSPadminV2
PKI options: -v -d /root/.dogtag/rhqa_pki/certs_db
PKI command: PKI OCSP Administrator for Non-TMS-OCSP -n PKI OCSP Administrator for Non-TMS-OCSP -c SECret.123 -h XXXXXXXXXX -p 32044 ocsp-user-add --fullName=OCSP AdminValid2 OCSPadminV2
Java command: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java -Djava.ext.dirs=/usr/share/pki/lib -Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties com.netscape.cmstools.cli.MainCLI -d /root/.dogtag/rhqa_pki/certs_db --verbose -n PKI OCSP Administrator for Non-TMS-OCSP -c SECret.123 -h XXXXXXXXXX -p 32044 ocsp-user-add --fullName=OCSP AdminValid2 OCSPadminV2
Server URI: http://XXXXXXXXXX:32044
Client security database: /root/.dogtag/rhqa_pki/certs_db
Message format: null
Command: ocsp-user-add "--fullName=OCSP AdminValid2" OCSPadminV2
Initializing security database
Getting internal token
Logging into NSS FIPS 140-2 User Private Key
Module: ocsp
Initializing PKIClient
HTTP request: GET /pki/rest/info HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:32044
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Set-Cookie: JSESSIONID=043531E7CAE47C7F8355B8B92EB07419; Path=/pki; HttpOnly
  Content-Type: application/xml
  Content-Length: 106
  Date: Thu, 15 Nov 2018 20:56:06 GMT
HTTP request: GET /ocsp/rest/account/login HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:32044
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 404 Not Found
  Server: Apache-Coyote/1.1
  Content-Type: text/html;charset=utf-8
  Content-Language: en
  Content-Length: 997
  Date: Thu, 15 Nov 2018 20:56:06 GMT
com.netscape.certsrv.base.PKIException: Not Found
	at com.netscape.certsrv.client.PKIConnection.handleErrorResponse(PKIConnection.java:467)
	at com.netscape.certsrv.client.PKIConnection.getEntity(PKIConnection.java:439)
	at com.netscape.certsrv.client.PKIClient.getEntity(PKIClient.java:107)
	at com.netscape.certsrv.account.AccountClient.login(AccountClient.java:46)
	at com.netscape.certsrv.client.SubsystemClient.login(SubsystemClient.java:47)
	at com.netscape.cmstools.cli.SubsystemCLI.login(SubsystemCLI.java:46)
	at com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:64)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:630)
	at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:666)
ERROR: Command '['/usr/lib/jvm/jre-1.8.0-openjdk/bin/java', '-Djava.ext.dirs=/usr/share/pki/lib', '-Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties', 'com.netscape.cmstools.cli.MainCLI', '-d', '/root/.dogtag/rhqa_pki/certs_db', '--verbose', '-n', 'PKI OCSP Administrator for Non-TMS-OCSP', '-c', 'SECret.123', '-h', 'XXXXXXXXXX', '-p', '32044', 'ocsp-user-add', '--fullName=OCSP AdminValid2', 'OCSPadminV2']' returned non-zero exit status 255

=================================================
TKS

[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSStartServlet.destroy(): shutdown server
[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSEngine.shutdown()
[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapBoundConnFactory(DirAclAuthz)
[16/Nov/2018:10:52:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: begins
[16/Nov/2018:10:52:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: SignedAuditLogger: event CLIENT_ACCESS_SESSION_TERMINATED
[16/Nov/2018:10:52:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: CS_CLIENT_ACCESS_SESSION_TERMINATED
[16/Nov/2018:10:52:51][LDAPConnThread-7 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: clientIP=XXXXXXXXXX serverIP=XXXXXXXXXX serverPort=7636 reason=CLOSE_NOTIFY
[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapAnonConnFactory(PasswdUserDBAuthentication)
[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: disconnecting connection 0
....
[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: SignedAuditLogger: event AUDIT_LOG_SHUTDOWN
[16/Nov/2018:10:52:51][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: LogFile: event type not selected: AUDIT_LOG_SHUTDOWN



# pki -v -d /root/.dogtag/rhqa_pki/certs_db -n "PKI TKS Administrator for TMS-TKS" -c SECret.123 -h `hostname` -p 23080 tks-user-add --fullName="TKS AdminValid4" TKSadminV4
PKI options: -v -d /root/.dogtag/rhqa_pki/certs_db
PKI command: PKI TKS Administrator for TMS-TKS -n PKI TKS Administrator for TMS-TKS -c SECret.123 -h XXXXXXXXXX -p 23080 tks-user-add --fullName=TKS AdminValid4 TKSadminV4
Java command: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java -Djava.ext.dirs=/usr/share/pki/lib -Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties com.netscape.cmstools.cli.MainCLI -d /root/.dogtag/rhqa_pki/certs_db --verbose -n PKI TKS Administrator for TMS-TKS -c SECret.123 -h XXXXXXXXXX -p 23080 tks-user-add --fullName=TKS AdminValid4 TKSadminV4
Server URI: http://XXXXXXXXXX:23080
Client security database: /root/.dogtag/rhqa_pki/certs_db
Message format: null
Command: tks-user-add "--fullName=TKS AdminValid4" TKSadminV4
Initializing security database
Getting internal token
Logging into NSS FIPS 140-2 User Private Key
Module: tks
Initializing PKIClient
HTTP request: GET /pki/rest/info HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:23080
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Set-Cookie: JSESSIONID=1484A46EA72E47340E6003FBFAF8DD0D; Path=/pki; HttpOnly
  Content-Type: application/xml
  Content-Length: 106
  Date: Fri, 16 Nov 2018 15:55:03 GMT
HTTP request: GET /tks/rest/account/login HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:23080
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 404 Not Found
  Server: Apache-Coyote/1.1
  Content-Type: text/html;charset=utf-8
  Content-Language: en
  Content-Length: 995
  Date: Fri, 16 Nov 2018 15:55:03 GMT
com.netscape.certsrv.base.PKIException: Not Found
	at com.netscape.certsrv.client.PKIConnection.handleErrorResponse(PKIConnection.java:467)
	at com.netscape.certsrv.client.PKIConnection.getEntity(PKIConnection.java:439)
	at com.netscape.certsrv.client.PKIClient.getEntity(PKIClient.java:107)
	at com.netscape.certsrv.account.AccountClient.login(AccountClient.java:46)
	at com.netscape.certsrv.client.SubsystemClient.login(SubsystemClient.java:47)
	at com.netscape.cmstools.cli.SubsystemCLI.login(SubsystemCLI.java:46)
	at com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:64)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:630)
	at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:666)
ERROR: Command '['/usr/lib/jvm/jre-1.8.0-openjdk/bin/java', '-Djava.ext.dirs=/usr/share/pki/lib', '-Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties', 'com.netscape.cmstools.cli.MainCLI', '-d', '/root/.dogtag/rhqa_pki/certs_db', '--verbose', '-n', 'PKI TKS Administrator for TMS-TKS', '-c', 'SECret.123', '-h', 'XXXXXXXXXX', '-p', '23080', 'tks-user-add', '--fullName=TKS AdminValid4', 'TKSadminV4']' returned non-zero exit status 255

====================================================

TPS
[16/Nov/2018:11:47:49][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSStartServlet.destroy(): shutdown server
[16/Nov/2018:11:47:49][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: CMSEngine.shutdown()
[16/Nov/2018:11:47:49][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapBoundConnFactory(DirAclAuthz)
[16/Nov/2018:11:47:49][LDAPConnThread-9 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: begins
[16/Nov/2018:11:47:49][LDAPConnThread-9 ldaps://XXXXXXXXXX:7636]: SignedAuditLogger: event CLIENT_ACCESS_SESSION_TERMINATED
[16/Nov/2018:11:47:49][LDAPConnThread-9 ldaps://XXXXXXXXXX:7636]: LogFile: event type not selected: CLIENT_ACCESS_SESSION_TERMINATED
[16/Nov/2018:11:47:49][LDAPConnThread-9 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: CS_CLIENT_ACCESS_SESSION_TERMINATED
[16/Nov/2018:11:47:49][LDAPConnThread-9 ldaps://XXXXXXXXXX:7636]: PKIClientSocketListener.alertReceived: clientIP=XXXXXXXXXX serverIP=XXXXXXXXXX serverPort=7636 reason=CLOSE_NOTIFY
[16/Nov/2018:11:47:49][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: Destroying LdapAnonConnFactory(DirBasedAuthentication)
[16/Nov/2018:11:47:49][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: disconnecting connection 0
....
[16/Nov/2018:11:47:49][ContainerBackgroundProcessor[StandardEngine[Catalina]]]: SignedAuditLogger: event AUDIT_LOG_SHUTDOWN

# tpsclient < format.tps
...
 -----
Output> Thread (0) status='0' time='80130 msec'
Result> Error - Operation 'ra_format' Failure (80130 msec)
Command>op=exit

# pki -v -d /root/.dogtag/rhqa_pki/certs_db -n "PKI TPS Administrator for TMS-TPS" -c SECret.123 -h `hostname` -p 30022 tps-user-add --fullName="TPS AdminValid" TPSadminV
PKI options: -v -d /root/.dogtag/rhqa_pki/certs_db
PKI command: PKI TPS Administrator for TMS-TPS -n PKI TPS Administrator for TMS-TPS -c SECret.123 -h XXXXXXXXXX -p 30022 tps-user-add --fullName=TPS AdminValid TPSadminV
Java command: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java -Djava.ext.dirs=/usr/share/pki/lib -Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties com.netscape.cmstools.cli.MainCLI -d /root/.dogtag/rhqa_pki/certs_db --verbose -n PKI TPS Administrator for TMS-TPS -c SECret.123 -h XXXXXXXXXX -p 30022 tps-user-add --fullName=TPS AdminValid TPSadminV
Server URI: http://XXXXXXXXXX:30022
Client security database: /root/.dogtag/rhqa_pki/certs_db
Message format: null
Command: tps-user-add "--fullName=TPS AdminValid" TPSadminV
Initializing security database
Getting internal token
Logging into NSS FIPS 140-2 User Private Key
Module: tps
Initializing PKIClient
HTTP request: GET /pki/rest/info HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:30022
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Set-Cookie: JSESSIONID=D8525BEEA64F17BD301F3CFFD491D3E2; Path=/pki; HttpOnly
  Content-Type: application/xml
  Content-Length: 106
  Date: Fri, 16 Nov 2018 17:03:43 GMT
HTTP request: GET /tps/rest/account/login HTTP/1.1
  Accept-Encoding: gzip, deflate
  Accept: application/xml
  Host: XXXXXXXXXX:30022
  Connection: Keep-Alive
  User-Agent: Apache-HttpClient/4.2.5 (java 1.5)
HTTP response: HTTP/1.1 404 Not Found
  Server: Apache-Coyote/1.1
  Content-Type: text/html;charset=utf-8
  Content-Language: en
  Content-Length: 995
  Date: Fri, 16 Nov 2018 17:03:43 GMT
com.netscape.certsrv.base.PKIException: Not Found
	at com.netscape.certsrv.client.PKIConnection.handleErrorResponse(PKIConnection.java:467)
	at com.netscape.certsrv.client.PKIConnection.getEntity(PKIConnection.java:439)
	at com.netscape.certsrv.client.PKIClient.getEntity(PKIClient.java:107)
	at com.netscape.certsrv.account.AccountClient.login(AccountClient.java:46)
	at com.netscape.certsrv.client.SubsystemClient.login(SubsystemClient.java:47)
	at com.netscape.cmstools.cli.SubsystemCLI.login(SubsystemCLI.java:46)
	at com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:64)
	at com.netscape.cmstools.cli.CLI.execute(CLI.java:345)
	at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:630)
	at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:666)
ERROR: Command '['/usr/lib/jvm/jre-1.8.0-openjdk/bin/java', '-Djava.ext.dirs=/usr/share/pki/lib', '-Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties', 'com.netscape.cmstools.cli.MainCLI', '-d', '/root/.dogtag/rhqa_pki/certs_db', '--verbose', '-n', 'PKI TPS Administrator for TMS-TPS', '-c', 'SECret.123', '-h', 'XXXXXXXXXX', '-p', '30022', 'tps-user-add', '--fullName=TPS AdminValid', 'TPSadminV']' returned non-zero exit status 255
==================================

Comment 5 Asha Akkiangady 2018-11-16 17:13:10 UTC

Marking the bug verified.

Comment 7 errata-xmlrpc 2019-01-29 17:21:55 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, 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/RHBA-2019:0168

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