#1735 Pkispawn: Behavior for Failed Installation
Closed: Invalid Opened by gkapoor.

While CS subsystem installation, "pkispawn in silent mode" fails sometimes
with exit status=1 .So my assumption is, if the Installation fails port binding
should not happen and pid shouldn't be created but i see that pid is generated
and ports are also getting binded.

Steps to Reproduce:

1. This can be easily reproduced in case of any kind of failure like
OSError,Parsing error.
2. Just start pkispawn.

Actual results:

Ports are getting binded and pid is getting generated

Expected results:

Until we have a clean installation with execution status 0 port and pid should
not be picked.

Additional info:

Here are some logs snip:
Below mentioned are few cases where i saw this behavior:
1. Due to OSError.
<Log snip>
2016-01-11 04:21:26 pkispawn    : ERROR    ....... OSError:  [Errno 12] Cannot
allocate memory!
2016-01-11 04:21:26 pkispawn    : DEBUG    ....... Error Type: OSError
2016-01-11 04:21:26 pkispawn    : DEBUG    ....... Error Message: [Errno 12]
Cannot allocate memory
2016-01-11 04:21:26 pkispawn    : DEBUG    .......   File "/usr/sbin/pkispawn",
line 597, in main
    rv = instance.spawn(deployer)
  File "/usr/lib/python2.7/site-packages/pki/server/deployment/scriptlets/confi
guration.py", line 112, in spawn
    data = deployer.config_client.construct_pki_configuration_data()
  File "/usr/lib/python2.7/site-packages/pki/server/deployment/pkihelper.py",
line 3992, in construct_pki_configuration_data
    self.set_admin_parameters(data)
  File "/usr/lib/python2.7/site-packages/pki/server/deployment/pkihelper.py",
line 4403, in set_admin_parameters
    None, None, True)
  File "/usr/lib/python2.7/site-packages/pki/server/deployment/pkihelper.py",
line 2637, in generate_certificate_request
    subprocess.check_call(command, stdout=fnull, stderr=fnull)
  File "/usr/lib64/python2.7/subprocess.py", line 537, in check_call
    retcode = call(*popenargs, **kwargs)
  File "/usr/lib64/python2.7/subprocess.py", line 524, in call
    return Popen(*popenargs, **kwargs).wait()
  File "/usr/lib64/python2.7/subprocess.py", line 711, in __init__
    errread, errwrite)
  File "/usr/lib64/python2.7/subprocess.py", line 1224, in _execute_child
    self.pid = os.fork()
<log snip ends>
2. Due to parse exception.
<Log snip>
2016-01-12 03:55:14,294 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : INFO     ....... constructing PKI configuration data.
2016-01-12 03:55:14,294 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : INFO     ....... executing 'certutil -R -d
/opt/FoobarTPS/tps/alias -s cn=PKI
Administrator,e=tpsadmin@os1.phx2.redhat.com,o=Foobar2.org -k ec -q nistp256 -z
/opt/FoobarTPS/tps/alias/noise -f /opt/FoobarTPS/tps/password.conf -o
/opt/FoobarTPS/tps/alias/admin_pkcs10.bin'
2016-01-12 03:55:14,362 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : INFO     ....... rm -f /opt/FoobarTPS/tps/alias/noise
2016-01-12 03:55:14,363 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : INFO     ....... BtoA
/opt/FoobarTPS/tps/alias/admin_pkcs10.bin
/opt/FoobarTPS/tps/alias/admin_pkcs10.bin.asc
2016-01-12 03:55:14,699 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : INFO     ....... configuring PKI configuration data.
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - Installation failed.
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : ERROR    ....... Exception from Java Configuration
Servlet: 500 Server Error: Internal Server Error
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : ERROR    ....... ParseError: not well-formed (invalid
token): line 1, column 0: {"Attributes":{"Attribute":[]},"ClassName":"com.netsc
ape.certsrv.base.PKIException","Code":500,"Message":"Errors in registering TPS
to CA, TKS or KRA: com.netscape.certsrv.base.PKIException: Error in generating
and exporting shared secret: java.security.InvalidKeyException: Key is not the
right type for this algorithm"}
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : DEBUG    ....... Error Type: ParseError
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : DEBUG    ....... Error Message: not well-formed (invalid
token): line 1, column 0
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG - pkispawn    : DEBUG    .......   File "/usr/sbin/pkispawn", line 597,
in main
2016-01-12 03:56:11,423 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -     rv = instance.spawn(deployer)
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -   File "/usr/lib/python2.7/site-packages/pki/server/deployment/scriptle
ts/configuration.py", line 116, in spawn
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -     json.dumps(data, cls=pki.encoder.CustomTypeEncoder))
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -   File
"/usr/lib/python2.7/site-packages/pki/server/deployment/pkihelper.py", line
3872, in configure_pki_data
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -     root = ET.fromstring(e.response.text)
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -   File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 1300, in
XML
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -     parser.feed(text)
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -   File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 1642, in
feed
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -     self._raiseerror(v)
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -   File "/usr/lib64/python2.7/xml/etree/ElementTree.py", line 1506, in
_raiseerror
2016-01-12 03:56:11,424 - pki.testlib.common.Qe_class.QeHost.geetika.cmd10 -
DEBUG -     raise err
<Log snip ends>
Pid/port details :
 netstat -pan | grep 16443
tcp6       0      0 :::16443                :::*                    LISTEN
21691/java
 ps -ef | grep 21691
pkiuser  21691     1 33 03:54 ?        00:00:35 /usr/lib/jvm/jre/bin/java
-DRESTEASY_LIB=/usr/share/java/resteasy-base
-Djava.library.path=/usr/lib64/nuxwdog-jni -classpath /usr/share/tomcat/bin/boo
tstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon
.jar -Dcatalina.base=/var/lib/pki/FoobarTPS -Dcatalina.home=/usr/share/tomcat
-Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/pki/FoobarTPS/temp
-Djava.util.logging.config.file=/var/lib/pki/FoobarTPS/conf/logging.properties
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.security.manager
-Djava.security.policy==/var/lib/pki/FoobarTPS/conf/catalina.policy
org.apache.catalina.startup.Bootstrap start
root     22575 14694  0 03:56 pts/3    00:00:00 grep --color=auto 2169

When deploying a new subsystem, pkispawn will execute several operations including:

  • if it's the first subsystem in the instance, create the Tomcat instance and start it
  • deploy the new subsystem into the instance

So if the subsystem deployment fails for any reason, pkispawn should stop immediately, but by that time the Tomcat is already running and bound to the port.

I think the current pkispawn behavior is fine. The pkispawn should not shutdown Tomcat because it may affect other subsystems already deployed, and it will complicate troubleshooting. Applications using the pkispawn (i.e. IPA, test scripts) should be aware of this behavior.

However, instead of shutting down Tomcat on pkispawn failure, the pkidestroy should clean up the system back to the state before pkispawn was run. So pkidestroy should work like this:

  • If pkispawn fails to deploy the first subsystem, pkidestroy should remove the new subsystem and the new Tomcat instance.
  • If pkispawn fails to deploy an additional subsystem, pkidestroy should remove the new subsystem only, but leave the Tomcat instance and the existing subsystems intact.

If pkidestroy does not work as described above please open a new ticket. Thanks.

Metadata Update from @gkapoor:
- Issue set to the milestone: 10.3.0

Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new
issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.

This issue has been cloned to GitHub and is available here:
https://github.com/dogtagpki/pki/issues/2293

If you want to receive further updates on the issue, please navigate to the
GitHub issue and click on Subscribe button.

Thank you for understanding, and we apologize for any inconvenience.

Metadata