HTL sites not displaying anymore jdk.nashorn.internal...

[sdouglasmc]

Running AEM 6.5.4
Java(TM) SE Runtime Environment(build 11.0.5+10-LTS)

Have you solved this issue?  We have no problem when we restart AEM, all things seem to work fine.  What appears to be out of the blue, all HTL related pages stop displaying with this same error.  If we restart, we are fine again.  

22.04.2020 19:47:06.739 ERROR [10.65.37.142 [1587577626473] GET /ca/en_ca.html HTTP/1.1] org.apache.sling.engine.impl.SlingRequestProcessorImpl service: Uncaught SlingException
jdk.nashorn.internal.runtime.ECMAException: ReferenceError: "use" is not defined
at jdk.scripting.nashorn/jdk.nashorn.internal.runtime.ECMAErrors.error(ECMAErrors.java:57)
at jdk.scripting.nashorn/jdk.nashorn.internal.runtime.ECMAErrors.referenceError(ECMAErrors.java:319)
at jdk.scripting.nashorn/jdk.nashorn.internal.runtime.ECMAErrors.referenceError(ECMAErrors.java:291)
at jdk.scripting.nashorn/jdk.nashorn.internal.objects.Global.__noSuchProperty__(Global.java:1616)
at jdk.scripting.nashorn.scripts/jdk.nashorn.internal.scripts.Script$Recompilation$63$\^eval\_/0x0000000802409c40.:program(<eval>:1)
at jdk.scripting.nashorn/jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:655)
at jdk.scripting.nashorn/jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:513)
at jdk.scripting.nashorn/jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:527)
at jdk.scripting.nashorn/jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:428)
at jdk.scripting.nashorn/jdk.nashorn.api.scripting.NashornScriptEngine$3.eval(NashornScriptEngine.java:521)
at org.apache.sling.scripting.core.impl.DefaultSlingScript.call(DefaultSlingScript.java:386) [org.apache.sling.scripting.core:2.0.56]
at org.apache.sling.scripting.core.impl.DefaultSlingScript.eval(DefaultSlingScript.java:184) [org.apache.sling.scripting.core:2.0.56]
at org.apache.sling.scripting.core.impl.DefaultSlingScript.service(DefaultSlingScript.java:491) [org.apache.sling.scripting.core:2.0.56]
at org.apache.sling.engine.impl.request.RequestData.service(RequestData.java:552) [org.apache.sling.engine:2.6.20]
at org.apache.sling.engine.impl.filter.SlingComponentFilterChain.render(SlingComponentFilterChain.java:44) [org.apache.sling.engine:2.6.20]
at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:82) [org.apache.sling.engine:2.6.20]
at com.day.cq.wcm.core.impl.WCMDeveloperModeFilter.doFilter(WCMDeveloperModeFilter.java:119) [com.day.cq.wcm.cq-wcm-core:5.12.118]
at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:72) [org.apache.sling.engine:2.6.20]
at com.day.cq.wcm.core.impl.WCMDebugFilter.doFilter(WCMDebugFilter.java:138) [com.day.cq.wcm.cq-wcm-core:5.12.118]

[Jörg_Hoh · Accepted solution]

Please raise a Daycare issue for that.

There must be an event which happens before and which troubles the Nashorn Scripting engine. Can you reproduce this issue?

[sdouglasmc]

Should it be even using the Nashorn Engine or should it be using Rhino?

[sdouglasmc]

Should it be even using the Nashorn Engine or should it be using Rhino? I'm going to do my best to try and replicate it. It seems to happen after a deployment where there is moderate traffic. We have 3 publish node

[sdouglasmc]

Should it be even using the Nashorn Engine or should it be using Rhino? 

It seems to happen after a deployment where there is moderate traffic. We have 3 publish nodes and keep 2 active. About 2 hours after a deployment, it happens on the 2 live instances.

I'm still trying my best to reproduce.

[Jörg_Hoh]

Good question; in the past there was only Rhino, but nowadays there is scripting support for Nashorn available (see https://github.com/apache/sling-org-apache-sling-fragment-nashorn); but on my 6.5.2 this bundle is not present. Can you check what engine is used when the rendering is working?

[sdouglasmc]

Right, I didn't see the bundle in mine either. My thought is that it is defaulting back to the one in the JDK, which is Nashorn, when whatever is happening, is happening.

[sdouglasmc]

Do you have a quick way to test for the scripting engine? I was just going to deactivate the rhino bundle..

[Jörg_Hoh]

Hm, doing this request and threaddumps in parallel in the hope to catch it?

[sdouglasmc]

Looks like on a good instance, Rhino is being used: Caused by: org.apache.sling.scripting.sightly.SightlyException: org.mozilla.javascript.EcmaError: ReferenceError: "granite" is not defined. (/libs/wcm/foundation/components/parsys/parsys.js#24) when I blew away the values in Apache Sling Scripting HTL JavaScript Use-API Factories Configuration (it keeps sightly:/libs/sling/sightly/js/internal/sly.js in by default it appears - but that file doesn't seem to appear in the repository - odd in itself)

[Jörg_Hoh]

ok, I would raise a Daycare ticket nevertheless. In parallel you can try to investigate why suddenly Nashorn is resolved. Probably something is going in OSGI so the priorities change.

[sdouglasmc]

I would open a ticket but I know the first thing they are going to ask is to send the recreation steps and I don't know them currently. I have confirmed this is the issue. It just so happens this was happening on a development server and restarting the org.apache.sling.scripting.core (549) bundle set things right without having to restart.

[Jörg_Hoh]

If restarting the scripting core bundle seems to fix issues, it seems that during runtime the default rendering was changed. Can you share the log entries before that this error message appears for the first time? It must have something to do with OSGI internals (services etc), so INFO messages from your code should be unrelated.

[sdouglasmc]

Finally got something worth while. If you have an email address, I can sent more to that but....

[sdouglasmc]

This seems to be the same thing I'm experiencing:

[sdouglasmc]

04.05.2020 16:23:23.383 *INFO* [Adobe Granite Maintenance Scheduler Update Task] com.adobe.granite.maintenance.impl.MaintenanceJobsManagerImpl Name='com.day.cq.audit.impl.AuditLogMaintenanceTask', Status='UNSCHEDULED', Result='', Details='{"window":"granite_weekly"}'
04.05.2020 16:23:23.383 *INFO* [Adobe Granite Maintenance Scheduler Update Task] com.adobe.granite.maintenance.impl.MaintenanceJobsManagerImpl Name='RevisionCleanupTask', Status='UNSCHEDULED', Result='', Details='{"window":"granite_daily"}'
04.05.2020 16:23:23.383 *INFO* [Adobe Granite Maintenance Scheduler Update Task] com.adobe.granite.maintenance.impl.MaintenanceJobsManagerImpl Name='LuceneBinariesCleanupTask', Status='UNSCHEDULED', Result='', Details='{"window":"granite_daily"}'
04.05.2020 16:23:23.387 *INFO* [OsgiInstallerImpl] org.apache.sling.scripting.sightly Service [org.apache.sling.scripting.sightly.impl.engine.SightlyScriptEngineFactory,37463, [javax.script.ScriptEngineFactory]] ServiceEvent UNREGISTERING
04.05.2020 16:23:23.390 *INFO* [Adobe Granite Maintenance Scheduler Update Task] org.apache.sling.hc.core Service [37848, [javax.management.DynamicMBean]] ServiceEvent UNREGISTERING
04.05.2020 16:23:23.398 *INFO* [Adobe Granite Maintenance Scheduler Update Task] com.adobe.granite.maintenance.core Service [37847, [org.apache.sling.hc.api.HealthCheck]] ServiceEvent UNREGISTERING
04.05.2020 16:23:23.407 *INFO* [OsgiInstallerImpl] org.apache.sling.scripting.sightly Service [org.apache.sling.scripting.sightly.impl.engine.extension.use.JavaUseProvider,37464, [org.apache.sling.scripting.sightly.use.UseProvider]] ServiceEvent UNREGISTERING
04.05.2020 16:23:23.410 *INFO* [EventAdminAsyncThread #4] org.apache.sling.scripting.core Service [37746, [org.apache.sling.api.resource.observation.ResourceChangeListener]] ServiceEvent UNREGISTERING
04.05.2020 16:23:23.412 *INFO* [Adobe Granite Maintenance Scheduler Update Task] org.apache.sling.hc.core Service [37850, [javax.management.DynamicMBean]] ServiceEvent UNREGISTERING
04.05.2020 16:23:23.418 *INFO* [OsgiInstallerImpl] org.apache.sling.scripting.sightly Service [org.apache.sling.scripting.sightly.impl.engine.SightlyScriptEngineFactory,37866, [javax.script.ScriptEngineFactory]] ServiceEvent REGISTERED
04.05.2020 16:23:23.420 *ERROR* [OsgiInstallerImpl] org.apache.sling.scripting.sightly bundle org.apache.sling.scripting.sightly:1.1.2.1_4_0 (557)[org.apache.sling.scripting.sightly.impl.engine.ExtensionRegistryService(3394)] : Error during instantiation of the implementation object (java.lang.NoClassDefFoundError: jdk/internal/reflect/ConstructorAccessorImpl)
java.lang.NoClassDefFoundError: jdk/internal/reflect/ConstructorAccessorImpl
at java.base/jdk.internal.misc.Unsafe.defineClass0(Native Method)
at java.base/jdk.internal.misc.Unsafe.defineClass(Unsafe.java:1192)
at java.base/jdk.internal.reflect.ClassDefiner.defineClass(ClassDefiner.java:63)
at java.base/jdk.internal.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:400)
at java.base/jdk.internal.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:394)
at java.base/java.security.AccessController.doPrivileged(Native Method)
at java.base/jdk.internal.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:393)
at java.base/jdk.internal.reflect.MethodAccessorGenerator.generateConstructor(MethodAccessorGenerator.java:92)
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:55)
at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
at org.apache.felix.scr.impl.inject.ComponentConstructor.newInstance(ComponentConstructor.java:309) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:277) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:114) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:982) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:955) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) [org.apache.felix.scr:2.1.16]
at org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:348)
at org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:248)
at org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:350)
at org.apache.felix.framework.Felix.getService(Felix.java:3954)
at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:450)
at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:86) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.inject.field.FieldHandler$ReferenceMethodImpl.getServiceObject(FieldHandler.java:519) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2308) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.prebind(DependencyManager.java:1154) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1568) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1029) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:935) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:900) [org.apache.felix.scr:2.1.16]
at org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:348)
at org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:248)
at org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:350)
at org.apache.felix.framework.Felix.getService(Felix.java:3954)
at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:450)
at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:86) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.inject.BindParameters.getServiceObject(BindParameters.java:47) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:664) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2308) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1805) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1788) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:435) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:325) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:294) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [org.apache.felix.scr:2.1.16]
at org.apache.felix.framework.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:990)
at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:838)
at org.apache.felix.framework.EventDispatcher.fireServiceEvent(EventDispatcher.java:545)
at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4833)
at org.apache.felix.framework.Felix.registerService(Felix.java:3804)
at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:328)
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:906) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:892) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:959) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:732) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ExtendedServiceEvent.activateManagers(ExtendedServiceEvent.java:59) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:142) [org.apache.felix.scr:2.1.16]
at org.apache.felix.framework.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:990)
at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:838)
at org.apache.felix.framework.EventDispatcher.fireServiceEvent(EventDispatcher.java:545)
at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4833)
at org.apache.felix.framework.Felix.registerService(Felix.java:3804)
at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:328)
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:906) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:892) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:959) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:732) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1045) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:999) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [org.apache.felix.scr:2.1.16]
at org.apache.felix.framework.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:990)
at org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:838)
at org.apache.felix.framework.EventDispatcher.fireServiceEvent(EventDispatcher.java:545)
at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4833)
at org.apache.felix.framework.Felix.registerService(Felix.java:3804)
at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:328)
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:906) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:892) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:128) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:959) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:732) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:1045) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.addedService(DependencyManager.java:999) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1216) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1137) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:944) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:880) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1168) [org.apache.felix.scr:2.1.16]
at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:125) [org.apache.felix.scr:2.1.16]

[Jörg_Hoh]

04.05.2020 16:23:23.387 *INFO* [OsgiInstallerImpl] org.apache.sling.scripting.sightly Service [org.apache.sling.scripting.sightly.impl.engine.SightlyScriptEngineFactory,37463, [javax.script.ScriptEngineFactory]] ServiceEvent UNREGISTERING

[Jörg_Hoh]

The log states that services are stopped which should handle the execution of these javascript scripts. Is there any indication what is causing these services to stop?

[sdouglasmc]

There was a code deployment. It failed activation when trying to register again.

[sdouglasmc]

This is the same issue we are facing: https://issues.apache.org/jira/browse/FELIX-6184

[Jörg_Hoh]

ok, this defintely seems to be something which is hard to solve here in the forum. I would recommend you to open an ticket with Adobe support.