[Freeipa-users] Failed to start pki-tomcatd Service

Thu Jul 16 07:29:21 UTC 2015

On (10/07/15 17:28), Alexandre Ellert wrote:
>
>> Le 30 juin 2015 à 10:16, Alexandre Ellert <aellert at numeezy.com> a écrit :
>> 
>> 
>>> Could you please provide the content of logfile:
>>> `/var/log/pki/pki-tomcat/ca/debug', around the time the error
>>> occurs?
>>> 
>>> Thanks,
>>> Fraser
>> 
>> When the pki-tomcatd service is trying to start, I see this message in /var/log/pki/pki-tomcat/ca/debug
>> 
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: ============================================
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: =====  DEBUG SUBSYSTEM INITIALIZED   =======
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: ============================================
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: CMSEngine: done init id=debug
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: CMSEngine: initialized debug
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: CMSEngine: initSubsystem id=log
>> [30/Jun/2015:10:02:13][localhost-startStop-1]: CMSEngine: ready to init id=log
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: done init id=log
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: initialized log
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: initSubsystem id=jss
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: ready to init id=jss
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: done init id=jss
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: initialized jss
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: initSubsystem id=dbs
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine: ready to init id=dbs
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: DBSubsystem: init()  mEnableSerialMgmt=true
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LdapBoundConnFactory: init 
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LdapBoundConnFactory:doCloning true
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LdapAuthInfo: init()
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LdapAuthInfo: init begins
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LdapAuthInfo: init ends
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: init: before makeConnection errorIfDown is true
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: makeConnection: errorIfDown true
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LdapJssSSLSocket set client auth cert nicknamesubsystemCert cert-pki-ca
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMS:Caught EBaseException
>> Internal Database Error encountered: Could not connect to LDAP server host ipa.mydomain.org <http://ipa.mydomain.org/> port 636 Error netscape.ldap.LDAPException: IO Error creating JSS SSL Socket (-1)
>> 	at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:658)
>> 	at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:934)
>> 	at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:865)
>> 	at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:362)
>> 	at com.netscape.certsrv.apps.CMS.init(CMS.java:189)
>> 	at com.netscape.certsrv.apps.CMS.start(CMS.java:1585)
>> 	at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:96)
>> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>> 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
>> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> 	at java.lang.reflect.Method.invoke(Method.java:606)
>> 	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:277)
>> 	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:274)
>> 	at java.security.AccessController.doPrivileged(Native Method)
>> 	at javax.security.auth.Subject.doAsPrivileged(Subject.java:536)
>> 	at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:309)
>> 	at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:169)
>> 	at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:123)
>> 	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1272)
>> 	at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1197)
>> 	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1087)
>> 	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5210)
>> 	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5493)
>> 	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
>> 	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
>> 	at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:133)
>> 	at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:156)
>> 	at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:145)
>> 	at java.security.AccessController.doPrivileged(Native Method)
>> 	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
>> 	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:632)
>> 	at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:672)
>> 	at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1862)
>> 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>> 	at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
>> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>> 	at java.lang.Thread.run(Thread.java:745)
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: CMSEngine.shutdown()
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LogFile:In log shutdown
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: SignedAuditEventFactory: create() message=[AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown
>> 
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: LogFile:In log shutdown
>> [30/Jun/2015:10:02:14][localhost-startStop-1]: SignedAuditEventFactory: create() message=[AuditEvent=AUDIT_LOG_SHUTDOWN][SubjectID=$System$][Outcome=Success] audit function shutdown
>> 
>> [30/Jun/2015:10:02:15][ajp-bio-127.0.0.1-8009-exec-1]: according to ccMode, authorization for servlet: caGetStatus is LDAP based, not XML {1}, use default authz mgr: {2}.
>> 
>> I checked that ns-slapd was running on port 636
>> # netstat -antp|grep 636
>> tcp6       0      0 :::636                  :::*                    LISTEN      22855/ns-slapd
>> 
>> After a quick search, I found this bug https://fedorahosted.org/freeipa/ticket/4666 <https://fedorahosted.org/freeipa/ticket/4666> is quite similar.
>> Many workarounds are suggested there but I’m confused about which could be efficient for me.
>> 
>Up plz.
>
I had a similar issue on fedora 21 or fedora 22.
The workarounds from freeipa ticket #4666 did not help for me either.
I found out that there was some problem with upgrading dogtag configuration.

You can try up ru upgrade manually. It might help you.
[root at vm-114 ~]# rpm -q --scripts pki-server
postinstall scriptlet (using /bin/sh):
## NOTE:  At this time, NO attempt has been made to update ANY PKI subsystem
##        from EITHER 'sysVinit' OR previous 'systemd' processes to the new
##        PKI deployment process

    echo "Upgrading server at `/bin/date`." >>
    /var/log/pki/pki-server-upgrade-10.2.4.log 2>&1
    /sbin/pki-server-upgrade --silent >>
    /var/log/pki/pki-server-upgrade-10.2.4.log 2>&1
    echo >> /var/log/pki/pki-server-upgrade-10.2.4.log 2>&1

    systemctl daemon-reload

In my case, it didn't help. So I updated freeipa to the latest version.
then I install similar new freeipa on another machine. So I had functional
dogtag. Then I tried to fix broken dogtag configuration using functional
configuration from 2nd freeipa. I would definitely recommend to backup data
from old freeipa before any manual updates.

Maybe Fraser would have a better advice.

LS