unsetScriptEngineFactory method throws exception on OH shutdown

[andrewfg]

On shutdown a 'bare' OH SNAPSHOT throws an exception The unsetScriptEngineFactory method has thrown an exception java.lang.IndexOutOfBoundsException: Index 0 out of bounds for length 0 -- it looks like the shutdown code fails because there are no rules defined.

2023-04-02 13:11:18.520 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Stopped HABPanel
2023-04-02 13:11:18.605 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2023-04-02 13:11:19.008 [ERROR] [e.script.ScriptTransformationService] - bundle org.openhab.core.automation.module.script:4.0.0.202303260308 (158)[org.openhab.core.automation.module.script.ScriptTransformationService(84)] : The unsetScriptEngineFactory method has thrown an exception
java.lang.IndexOutOfBoundsException: Index 0 out of bounds for length 0
	at jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:64) ~[?:?]
	at jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:70) ~[?:?]
	at jdk.internal.util.Preconditions.checkIndex(Preconditions.java:266) ~[?:?]
	at java.util.Objects.checkIndex(Objects.java:359) ~[?:?]
	at java.util.ArrayList.get(ArrayList.java:427) ~[?:?]
	at java.util.Collections$UnmodifiableList.get(Collections.java:1347) ~[?:?]
	at org.openhab.core.automation.module.script.internal.ScriptEngineFactoryHelper.getPreferredMimeType(ScriptEngineFactoryHelper.java:62) ~[?:?]
	at org.openhab.core.automation.module.script.ScriptTransformationService.unsetScriptEngineFactory(ScriptTransformationService.java:275) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:245) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:687) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod$NotResolved.invoke(BaseMethod.java:641) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:531) ~[?:?]
	at org.apache.felix.scr.impl.inject.methods.BindMethod.invoke(BindMethod.java:42) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:2212) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:1948) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:430) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:165) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.ungetService(SingleComponentManager.java:1043) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$2.run(ServiceFactoryUse.java:273) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$2.run(ServiceFactoryUse.java:1) ~[org.eclipse.osgi-3.18.0.jar:?]
	at java.security.AccessController.doPrivileged(AccessController.java:318) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryUngetService(ServiceFactoryUse.java:270) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.ungetService(ServiceFactoryUse.java:167) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.ungetService(ServiceConsumer.java:53) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.ungetService(ServiceRegistrationImpl.java:632) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.ungetService(ServiceRegistry.java:613) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.ungetService(BundleContextImpl.java:703) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.safeUngetService(SingleRefPair.java:109) ~[?:?]
	at org.apache.felix.scr.impl.manager.SingleRefPair.ungetServiceObjects(SingleRefPair.java:74) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$AbstractCustomizer.ungetService(DependencyManager.java:231) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:416) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:304) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1258) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1152) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:1012) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1192) ~[?:?]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:241) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:952) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:915) ~[?:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:140) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:994) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:844) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:825) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.deactivateComponentManager(DependencyManager.java:2636) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager.access$400(DependencyManager.java:59) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.removedService(DependencyManager.java:1356) ~[?:?]
	at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.removedService(DependencyManager.java:1225) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1258) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1152) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:1012) ~[?:?]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1192) ~[?:?]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:116) ~[?:?]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:123) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:961) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:937) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:874) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:241) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:952) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:915) ~[?:?]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:140) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:994) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:844) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:825) ~[?:?]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:589) ~[?:?]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:722) ~[?:?]
	at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:492) ~[?:?]
	at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:652) ~[?:?]
	at org.apache.felix.scr.impl.Activator.access$300(Activator.java:74) ~[?:?]
	at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:490) ~[?:?]
	at org.apache.felix.scr.impl.AbstractExtender$1.run(AbstractExtender.java:216) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at org.apache.felix.scr.impl.AbstractExtender.destroyExtension(AbstractExtender.java:238) ~[?:?]
	at org.apache.felix.scr.impl.AbstractExtender.bundleChanged(AbstractExtender.java:132) ~[?:?]
	at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:255) ~[?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:949) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:229) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.doStop(Module.java:658) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.stop(Module.java:521) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1888) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1763) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:275) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:208) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.doStop(Module.java:660) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.Module.stop(Module.java:521) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:207) ~[org.eclipse.osgi-3.18.0.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:226) ~[org.eclipse.osgi-3.18.0.jar:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]

[J-N-K]

Which script engines did you install? Only DSL?

[mhilbush]

I just saw this on my systems running build 3392. I have DSL and jsscripting installed.

[J-N-K]

@jimtng While this code is removed in #3487, the new code is similar. It seems that some script engine factories (I don't no which one) seem to report an empty list for supported script types, when the factory is disposed. This will also lead to an empty preferred extension and the corresponding transformation service is not deactivated, but they'll no longer work. Maybe we should use the factory itself as key in the list of created transformation services, WDYT?

[andrewfg]

Which script engines did you install?

As I said, it was a 'bare' install. So it has (or has not) whatever script engines get installed by default.

[jimtng]

@jimtng While this code is removed in #3487, the new code is similar. It seems that some script engine factories (I don't no which one) seem to report an empty list for supported script types, when the factory is disposed. This will also lead to an empty preferred extension and the corresponding transformation service is not deactivated, but they'll no longer work.

I did encounter an empty extension.

Unless the factory changed its answer about scriptTypes during its lifetime, it won't be added in the first place, because it's checked during service creation

Maybe we should use the factory itself as key in the list of created transformation services, WDYT?

@J-N-K I guess this might be the safer way to go

[J-N-K]

Even an empty extension should not happen (although it might be the factory only reports MIME-types). But in this case it means that .getScriptTypes returns an empty list, which is even more ridiculous. I'll try to check if I can reproduce that.

[jimtng]

IIRC, it was reported by GenericScriptEngineFactory - its getScriptTypes returns an empty list

[J-N-K]

Yes, I figured that out a minute ago. I'm wondering why we have that at all, all scripting add-ons inherit from AbstractScriptEngineFactory or implement ScriptEngineFactory.