LG-TV binding throws exception

Boby · December 8, 2017, 6:50pm

I have troubles integrating my 2012 LG TV into openhab.
I reinstalled the binding - and now I get the following error during the startup:

2017-12-08 19:11:26.714 [ERROR] [org.openhab.binding.lgtv            ] - [org.openhab.binding.lgtv(199)] The deactivate method has thrown an exception

java.lang.IllegalArgumentException: Alias [/udap/api/event] was never registered

	at org.ops4j.pax.web.service.internal.HttpServiceStarted.unregister(HttpServiceStarted.java:278)

	at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregister(HttpServiceProxy.java:77)

	at org.openhab.binding.lgtv.lginteraction.LgTvMessageReader.deactivate(LgTvMessageReader.java:178)

	at org.openhab.binding.lgtv.lginteraction.LgTvMessageReader.stopserver(LgTvMessageReader.java:195)

	at org.openhab.binding.lgtv.internal.LgtvConnection.closeConnection(LgtvConnection.java:158)

	at org.openhab.binding.lgtv.internal.LgtvBinding.closeAllConnections(LgtvBinding.java:378)

	at org.openhab.binding.lgtv.internal.LgtvBinding.deactivate(LgtvBinding.java:94)

	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_152]

	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_152]

	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_152]

	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_152]

	at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[32:org.apache.felix.scr:2.0.6]

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

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

	at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:302)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:343)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:152)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:813)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[32:org.apache.felix.scr:2.0.6]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_152]

	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_152]

	at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[32:org.apache.felix.scr:2.0.6]

	at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[32:org.apache.felix.scr:2.0.6]

	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:419)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]

	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1293)[8:org.apache.karaf.features.core:4.0.8]

	at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:612)[8:org.apache.karaf.features.core:4.0.8]

	at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1176)[8:org.apache.karaf.features.core:4.0.8]

	at org.apache.karaf.features.internal.service.FeaturesServiceImpl$1.call(FeaturesServiceImpl.java:1074)[8:org.apache.karaf.features.core:4.0.8]

	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_152]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_152]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_152]

	at java.lang.Thread.run(Thread.java:748)[:1.8.0_152]

2017-12-08 19:11:27.349 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-lgtv1'

Any ideas?

Boby · December 8, 2017, 7:11pm

Rebooted twice, but nothing changed. I’m running openHABian on a RPI2 at this version:
openHAB 2.1.0-1 (Release Build)

Boby · December 8, 2017, 7:13pm

Switching now to the snapshot, maybe it helps

Boby · December 8, 2017, 7:45pm

Didn’t help. Still throws the same exception and the binding gets uninstalled automatically:

2017-12-08 20:37:08.797 [thome.event.ExtensionEvent] - Extension 'binding-lgtv1' has been installed.
2017-12-08 20:42:31.040 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-lgtv1'
2017-12-08 20:42:31.055 [thome.event.ExtensionEvent] - Extension 'binding-lgtv1' has been uninstalled.

Yep, it’s really annoying it’s not working after that long time, but unfortunately I don’t speak JAVA otherwise I would have solved it myself. But I’ll try to file a bug report in github.

namraccr · December 9, 2017, 1:25am

I think you need to look at the earlier portion of the log file to determine if the binding ever registered properly.

To be more specific, you want to see messages like:

lgtv servlet activate called
Started LgTv Servlet at ...

Boby · December 9, 2017, 4:18pm

Hi everyone,
I downloaded my logfile and filtered out everything with the text “binding.lgtv.internal.lgtvconnection”.
Here’s the result:

2017-12-08 20:41:37.997 [INFO ] [binding.lgtv.internal.LgtvConnection] - sethttpservice called
2017-12-08 20:41:37.995 [INFO ] [binding.lgtv.internal.LgtvConnection] - sethttpservice called
2017-12-08 20:41:38.069 [INFO ] [binding.lgtv.internal.LgtvConnection] - lgtv servlet activate called
2017-12-08 20:41:38.154 [ERROR] [binding.lgtv.internal.LgtvConnection] - sendtotv but connection status is CS_NOTCONNECTED
2017-12-08 20:41:38.290 [INFO ] [binding.lgtv.internal.LgtvConnection] - lgtv connectionstatus of ip=192.168.1.99 changed from CS_NOTCONNECTED to CS_PAIRED
2017-12-08 20:41:38.304 [INFO ] [binding.lgtv.internal.LgtvConnection] - sendpairkey with result=200 successconnectionstatus=CS_PAIRED
2017-12-08 20:41:38.338 [ERROR] [binding.lgtv.internal.LgtvConnection] - sendtotv but connection status is CS_NOTCONNECTED
2017-12-08 20:41:38.533 [INFO ] [binding.lgtv.internal.LgtvConnection] - lgtv connectionstatus of ip=192.168.1.99 changed from CS_NOTCONNECTED to CS_PAIRED
2017-12-08 20:41:38.538 [INFO ] [binding.lgtv.internal.LgtvConnection] - sendpairkey with result=200 successconnectionstatus=CS_PAIRED
2017-12-08 20:41:38.553 [ERROR] [binding.lgtv.internal.LgtvConnection] - sendtotv but connection status is CS_NOTCONNECTED
2017-12-08 20:41:38.587 [INFO ] [binding.lgtv.internal.LgtvConnection] - lgtv connectionstatus of ip=192.168.1.99 changed from CS_NOTCONNECTED to CS_PAIRED
2017-12-08 20:41:38.572 [INFO ] [binding.lgtv.internal.LgtvConnection] - Started LgTv Servlet at /udap/api/event
2017-12-08 20:41:38.599 [INFO ] [binding.lgtv.internal.LgtvConnection] - sendpairkey with result=200 successconnectionstatus=CS_PAIRED
2017-12-08 20:41:38.612 [ERROR] [binding.lgtv.internal.LgtvConnection] - sendtotv but connection status is CS_NOTCONNECTED
2017-12-08 20:41:38.682 [INFO ] [binding.lgtv.internal.LgtvConnection] - lgtv connectionstatus of ip=192.168.1.99 changed from CS_NOTCONNECTED to CS_PAIRED
2017-12-08 20:41:38.694 [INFO ] [binding.lgtv.internal.LgtvConnection] - sendpairkey with result=200 successconnectionstatus=CS_PAIRED
2017-12-08 20:41:38.751 [INFO ] [binding.lgtv.internal.LgtvConnection] - sendpairkey with result=200 successconnectionstatus=CS_PAIRED
2017-12-08 20:41:38.837 [INFO ] [binding.lgtv.internal.LgtvConnection] - sendpairkey with result=200 successconnectionstatus=CS_PAIRED
2017-12-08 20:42:29.936 [INFO ] [binding.lgtv.internal.LgtvConnection] - Stopped LgTv Servlet

So, it sems it works for a while - and then the problems start.

The final exception looks this way:

![grafik|690x416](upload://uYmQvgjnfWvXXHPN9Q8LGh3FzfJ.png)2017-12-08 20:42:29.944 [ERROR] [org.openhab.binding.lgtv            ] - [org.openhab.binding.lgtv(207)] The deactivate method has thrown an exception
java.lang.IllegalArgumentException: Alias [/udap/api/event] was never registered
at org.ops4j.pax.web.service.internal.HttpServiceStarted.unregister(HttpServiceStarted.java:313) ~[?:?]
at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregister(HttpServiceProxy.java:78) ~[?:?]
at org.openhab.binding.lgtv.lginteraction.LgTvMessageReader.deactivate(LgTvMessageReader.java:178) ~[?:?]
at org.openhab.binding.lgtv.lginteraction.LgTvMessageReader.stopserver(LgTvMessageReader.java:195) ~[?:?]
at org.openhab.binding.lgtv.internal.LgtvConnection.closeConnection(LgtvConnection.java:158) ~[?:?]
at org.openhab.binding.lgtv.internal.LgtvBinding.closeAllConnections(LgtvBinding.java:378) ~[?:?]
at org.openhab.binding.lgtv.internal.LgtvBinding.deactivate(LgtvBinding.java:94) ~[?:?]
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:498) ~[?:?]
at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:229) ~[?:?]
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:650) ~[?:?]
at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:506) ~[?:?]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:299) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:344) ~[?:?]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:153) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:814) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:788) ~[?:?]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:580) ~[?:?]
at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706) ~[?:?]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523) ~[?:?]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:439) ~[?:?]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54) ~[?:?]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:293) ~[?:?]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:285) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:307) ~[?:?]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:181) ~[?:?]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:903) ~[?:?]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) ~[?:?]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) ~[?:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) ~[?:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) ~[?:?]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) ~[?:?]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:156) ~[?:?]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) ~[?:?]
at org.eclipse.osgi.container.Module.doStop(Module.java:634) ~[?:?]
at org.eclipse.osgi.container.Module.stop(Module.java:498) ~[?:?]
at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:410) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1367) ~[?:?]
at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:642) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1248) ~[?:?]
at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$1(FeaturesServiceImpl.java:1147) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2017-12-08 20:42:31.040 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-lgtv1'

Boby · December 9, 2017, 4:19pm

What does this exactly mean?

namraccr · December 10, 2017, 11:19pm

Are you stopping the binding? That’s what this looks like.

If not, you need to examine the log message that occur near this statement.

namraccr · December 10, 2017, 11:21pm

And to get the best information, you should set the logging for the binding to DEBUG.

Boby · December 26, 2017, 11:52am

Seems like the issue has been fixed (need to test it though):
https://github.com/openhab/openhab1-addons/issues/5381

Boby · December 26, 2017, 1:09pm

Had some time to test it - and the error was fixed, no exception anymore. Thank you!
Now I get an error when I try the APP_EXECUTE command:
[ERROR] [binding.lgtv.internal.LgtvConnection] - envelope=null maybe not connected
–> Will open another thread for this to keep this topic clean