Instance hangs for ~15 minutes after sling.properties change

[DevDev123]

Hey everyone,

I set up AEM Forms (the OSGI flavour) on top of AEM 6.3 according to this guide: Installing and configuring AEM 6.3 forms

After the "Boot delegate RSA and BouncyCastle libraries" step my instance needs up to 15 minutes to start up.

What I did was adding following lines:

sling.bootdelegation.class.com.rsa.jsafe.provider.JsafeJCE=com.rsa.*

sling.bootdelegation.class.org.bouncycastle.jce.provider.BouncyCastleProvider=org.bouncycastle.*

to the sling.properties file. When I remove the RSA.Jsafe line the instance boots up fast again. Did you guys experience something like this? The log seems fine.

Thanks

D

[smacdonald2008]

How much RAM do you have, whats is your HEAP size. There are many variables that can play a role here. When you refresh Sling Settings, there are many services that are refreshed.

[DevDev123]

Hi smacdonald2008​,

the instance is started with -Xmx1024m -XX:MaxMetaspaceSize=512m. The MemTotal is listed with 12139656 kB.

This is a demo author instance with zero load.

This gap happens on every startup - not only after a change of the sling.properties file.

[Jörg_Hoh]

Please post the relevant log statements of the error.log during the startup. I suppose that there is huge time gap (several minutes) between 2 log statements. Can you check that?

Jörg

[smacdonald2008]

If this continues - please log a ticket so support can investigate.

[DevDev123]

Hi Jörg,

here are the log statements you asked for:

......

01.02.2018 14:03:22.338 *INFO* [FelixStartLevel] adobe-aemfd-signatures BundleEvent STARTING

01.02.2018 14:03:24.368 *INFO* [sling-default-2] com.day.cq.wcm.mobile.core.impl.devicespecs.WurflXmlLoader Checking if wurfl.xml needs parsing...

01.02.2018 14:03:24.373 *INFO* [sling-default-2] com.day.cq.wcm.mobile.core.impl.devicespecs.WurflXmlLoader /var/mobile/devicespecs already contains data of /libs/wcm/mobile/devicespecs/wurfl.xml, update not needed

01.02.2018 14:03:30.580 *INFO* [discovery.connectors.common.runner.5b6b417b-e744-4b33-84cf-0a10dbc57028.connectorPinger] org.apache.sling.discovery.commons.providers.base.MinEventDelayHandler handlesNewView: only properties differ, hence no delaying applicable

01.02.2018 14:03:30.580 *INFO* [discovery.connectors.common.runner.5b6b417b-e744-4b33-84cf-0a10dbc57028.connectorPinger] org.apache.sling.discovery.commons.providers.base.ViewStateManagerImpl handleNewViewNonDelayed: properties changed to: DefaultTopologyView[current=true, num=1, instances=[clusterId=02266a28-895b-4cd9-806b-8021a2b187de, instances=[id=5b6b417b-e744-4b33-84cf-0a10dbc57028, isLeader=true, isLocal=true]]]

01.02.2018 14:03:30.580 *INFO* [discovery.connectors.common.runner.5b6b417b-e744-4b33-84cf-0a10dbc57028.connectorPinger] org.apache.sling.discovery.commons.providers.base.ViewStateManagerImpl enqueueForAll: sending topologyEvent TopologyEvent [type=PROPERTIES_CHANGED, oldView=DefaultTopologyView[current=false, num=1, instances=5b6b417b-e744-4b33-84cf-0a10dbc57028[local=true,leader=true]], newView=DefaultTopologyView[current=true, num=1, instances=5b6b417b-e744-4b33-84cf-0a10dbc57028[local=true,leader=true]]], to all (17) listeners

01.02.2018 14:03:30.582 *INFO* [Discovery-AsyncEventSender] org.apache.sling.discovery.oak.OakDiscoveryService changePropagationListener.handleTopologyEvent: topology changed - propagate through connectors

01.02.2018 14:03:30.582 *INFO* [Discovery-AsyncEventSender] org.apache.sling.discovery.oak.pinger.OakViewChecker triggerAsyncConnectorPing: firing job to trigger heartbeat

01.02.2018 14:03:54.316 *INFO* [qtp105398805-209] org.apache.sling.startupfilter.impl.StartupFilterImpl Reloaded list of StartupInfoProvider: []

01.02.2018 14:03:59.012 *INFO* [oak-repository-executor-1] com.adobe.granite.repository Service [6901, [org.apache.jackrabbit.oak.api.jmx.SessionMBean]] ServiceEvent REGISTERED (100 times)

--- long pause ---

01.02.2018 14:20:57.864 *INFO* [FelixStartLevel] adobe-aemfd-signatures BundleEvent STARTED

01.02.2018 14:20:57.872 *INFO* [FelixStartLevel] adobe-aemfd-signatures Service [com.adobe.fd.signatures.impl.SignatureServiceImpl,6991, [com.adobe.fd.signatures.SignatureService]] ServiceEvent REGISTERED

01.02.2018 14:20:57.917 *INFO* [FelixStartLevel] adobe-aemfd-docassurance Service [com.adobe.fd.docassurance.client.api.impl.DocAssuranceServiceImpl,6992, [com.adobe.fd.docassurance.client.api.DocAssuranceService]] ServiceEvent REGISTERED

01.02.2018 14:20:57.922 *INFO* [FelixStartLevel] adobe-aemfd-signatures-hsm-bmc BundleEvent RESOLVED

01.02.2018 14:20:57.922 *INFO* [FelixStartLevel] adobe-aemfd-signatures-hsm-bmc BundleEvent STARTING

01.02.2018 14:20:57.922 *INFO* [FelixStartLevel] adobe-aemfd-signatures-hsm-bmc BundleEvent STARTED

01.02.2018 14:20:57.931 *INFO* [FelixStartLevel] adobe-aemfd-signatures-hsm-bmc Service [com.adobe.livecycle.signatures.hsm.bmcclient.mbean.HSMBMCMgmtService,6993, [com.adobe.livecycle.signatures.hsm.bmcclient.mbean.HSMBMCMgmtServiceMBean, com.adobe.service.ServiceMBean, com.adobe.service.PoolingAttributes, com.adobe.service.ProcessAttributes, com.adobe.jmx.statistics.StatisticsHost]] ServiceEvent REGISTERED

01.02.2018 14:20:57.969 *ERROR* [FelixStartLevel] adobe-aemfd-signatures-hsm-bmc [com.adobe.livecycle.signatures.hsm.bmcclient.mbean.HSMBMCMgmtService(3543)] The activate method has thrown an exception (java.lang.NullPointerException)

java.lang.NullPointerException: null

at com.adobe.livecycle.signatures.hsm.bmcclient.mbean.HSMBMCMgmtService.makeClasspathFromDir(HSMBMCMgmtService.java:122)

at com.adobe.livecycle.signatures.hsm.bmcclient.mbean.HSMBMCMgmtService.onStartService(HSMBMCMgmtService.java:79)

at com.adobe.service.Service.start(Service.java:425)

at com.adobe.service.Service.initialize(Service.java:407)

at com.adobe.service.Service.activate(Service.java:82)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:497)

at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)

at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)

at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)

at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)

at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)

at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)

at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:298)

at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:109)

at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906)

at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:749)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:675)

at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:430)

at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657)

at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341)

at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:390)

at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54)

at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:265)

at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)

at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)

at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)

at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)

at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)

at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)

at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)

at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)

at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4542)

at org.apache.felix.framework.Felix.startBundle(Felix.java:2173)

at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1372)

at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)

at java.lang.Thread.run(Thread.java:745)

01.02.2018 14:20:57.972 *INFO* [FelixStartLevel] com.adobe.osgi.wrapper.beanlib BundleEvent STARTING

and so on ..

Thanks for the support guys. Its much appreciated!

Regards

D

[Jörg_Hoh]

Hi,

is it correct, that you have redhat linux (or a derivate from it, like Centos or Oracle Linux) installed? Then install the rng-tools package (or as alternative the havegd package) from the distribution repository (yum install rng-tools). That should help.

The problem in your case is that the signature bundle of AEM forms is initializing it's security module, and therefor needs a lot of entropy. Because the OS cannot provide enough entroy (via /dev/random) it takes a very long time until enough entropy is produced. These tools mitigate that and make sure that always enough entropy is available.

Jörg

[DevDev123]

Thanks Jörg! That seemed to do the trick for me.

If others have the same Issue (on Cent OS) you guys should have a look at 3.4. Using the Random Number Generator - Red Hat Customer Portal after installing rng-tools.

Maybe you need to alter the init script at /usr/lib/systemd/system/rngd.service.

Regards

D