Highlighted

Instance hangs for ~15 minutes after sling.properties change

Avatar

Avatar

DevDev123

Avatar

DevDev123

DevDev123

30-01-2018

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

Replies

Highlighted

Avatar

Avatar

smacdonald2008

Total Posts

12.7K

Likes

1.4K

Correct Answer

2.3K

Avatar

smacdonald2008

Total Posts

12.7K

Likes

1.4K

Correct Answer

2.3K
smacdonald2008

30-01-2018

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.

Highlighted

Avatar

Avatar

Jörg_Hoh

Employee

Total Posts

3.0K

Likes

916

Correct Answer

1.0K

Avatar

Jörg_Hoh

Employee

Total Posts

3.0K

Likes

916

Correct Answer

1.0K
Jörg_Hoh
Employee

30-01-2018

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

Highlighted

Avatar

Avatar

smacdonald2008

Total Posts

12.7K

Likes

1.4K

Correct Answer

2.3K

Avatar

smacdonald2008

Total Posts

12.7K

Likes

1.4K

Correct Answer

2.3K
smacdonald2008

31-01-2018

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

Highlighted

Avatar

Avatar

DevDev123

Avatar

DevDev123

DevDev123

01-02-2018

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.

Highlighted

Avatar

Avatar

DevDev123

Avatar

DevDev123

DevDev123

01-02-2018

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

Highlighted

Avatar

Avatar

Jörg_Hoh

Employee

Total Posts

3.0K

Likes

916

Correct Answer

1.0K

Avatar

Jörg_Hoh

Employee

Total Posts

3.0K

Likes

916

Correct Answer

1.0K
Jörg_Hoh
Employee

01-02-2018

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

Highlighted

Avatar

Avatar

DevDev123

Avatar

DevDev123

DevDev123

01-02-2018

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