search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.9k stars 3.59k forks source link

[SMAEnergyMeter] Problems with 4.2.1 #17280

Closed Hoerli1337 closed 1 month ago

Hoerli1337 commented 3 months ago

Hello Community,

I think I have to report an error :( After creating a thread in the openHAB forum, I should now open an issue here. (community.openhab.org)

I have an SMA inverter with the “SMA Sunny Home Manager 2.0” energy meter. The Home Manager can be read out with the binding “SMA Energy Meter Binding”. This has worked more or less well so far. Since openHAB 4.2.1, however, nothing works anymore. No more values are read out.

What have I tried so far?

Examined the multicast traffic => The traffic arrives and I can intercept it via Wireshark, for example. (At first I suspected a router update as the problem, but this is not the case)

Created the Thing again => Always gets stuck in the Unknown status

Restarted openHAB => Did not help

Cleared the cache => Did not help

Reinstalled the binding => The following error appears in the error log when uninstalling:

2024-08-15 11:08:38.986 [WARN ] [$UnstoppableScheduledExecutorService] - shutdownNow() invoked on a shared thread pool 'OH-binding-smaenergymeter-listener'. This is a bug, please submit a bug report
java.lang.IllegalStateException: null
    at org.openhab.core.common.ThreadPoolManager$UnstoppableExecutorService.shutdownNow(ThreadPoolManager.java:242) ~[?:?]
    at org.openhab.binding.smaenergymeter.internal.packet.DefaultPacketListenerRegistry.shutdown(DefaultPacketListenerRegistry.java:67) ~[?:?]
    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.invoke(BaseMethod.java:531) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:421) ~[?:?]
    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$SingleStaticCustomizer.close(DependencyManager.java:1426) ~[?:?]
    at org.apache.felix.scr.impl.manager.DependencyManager.deactivate(DependencyManager.java:1568) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateDependencyManagers(AbstractComponentManager.java:1280) ~[?:?]
    at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:854) ~[?:?]
    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.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:472) ~[org.eclipse.osgi-3.18.0.jar:?]
    at org.apache.karaf.features.internal.service.BundleInstallSupportImpl.stopBundle(BundleInstallSupportImpl.java:171) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1165) ~[?:?]
    at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:783) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1069) ~[?:?]
    at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]

My system:

After reinstalling the binding about 5 times, I was able to manually add the Home Manager again. It is now shown as online. The automatic discovery did not work. Not even by pressing the SCAN button. Apparently there is a problem with V4.2.1 :(

lsiepel commented 2 months ago

Could you try this version: https://1drv.ms/u/s!AnMcxmvEeupwjv9m9osRyk-2jY9whA?e=ICEKNF should be usable for openHAB 4.2.0+

  1. Uninstall the current binding
  2. Drop this jar file in your addon folder
  3. Check your log when performing a discovery scan and upload it here if you encounter issues.
Hoerli1337 commented 2 months ago

I uninstalled the binding and added your version. I have kept the items to see if anything changes.

Everything looks normal so far.

I have also tested the search, unfortunately without success. I'll see how well the version with the manual addition behaves.

lsiepel commented 2 months ago

Good to see that the binding is working somehow again.

Regarding the discovery, did you scan while a Thing was added/configured or did you delete the Thing and then perform a scan? Would be nice if you can provide a debug log while you perform a scan.

lsiepel commented 2 months ago

@Hoerli1337 could you provide a debug log to determine if there is another issue left to fix?

Hoerli1337 commented 2 months ago

Sorry for the late feedback, unfortunately I don't check Github every day. I ran the version on my Raspberry Pi and couldn't find anything negative. I also installed the binding in a new openHAB instance in an LXC. The SMA meter was found and all channels could be created correctly. According to the log, there are no errors.

I think the version is working well so far :)

2024-09-08 14:32:12.974 [DEBUG] [overy.SMAEnergyMeterDiscoveryService] - Adding a new SMA Energy Meter with S/N 'XXXXXXXXXXX' to inbox
2024-09-08 14:32:12.975 [DEBUG] [overy.SMAEnergyMeterDiscoveryService] - Thing discovered 'DiscoveryResult [thingUID=smaenergymeter:energymeter:XXXXXXXXXXX, properties={serialNumber=XXXXXXXXXXX, vendor=SMA}, representationProperty=serialNumber, flag=NEW, label=SMA Energy Meter #XXXXXXXXXXX, bridgeUID=null, ttl=-1, timestamp=2024-09-08T14:32:12.974620006Z]'
mstormi commented 1 month ago

I'm getting the exact same error with 4.3.0M2, isn't this fix supposed to be in there ? The SHM thing is stuck in 'unknown' state and a bundle restart results in the log below.

FWIW, scanning does not find any SHM, and on manual thing creation I cannot add any serial Number. But that OH complains about as being mandatory. Created via .thing for now. (sidenote question: is that a decimal value as printed on the device or some other format such as hex ?)

2024-10-07 22:17:09.230 [DEBUG] [f.shell.impl.console.osgi.LoggingCommandSessionListener] - Executing command: 'bundle:restart org.openhab.binding.smaenergymeter'
2024-10-07 22:17:09.241 [DEBUG] [org.apache.karaf.shell.impl.action.osgi.CommandExtender] - org.openhab.binding.smaenergymeter (271): Starting destruction process
2024-10-07 22:17:09.243 [DEBUG] [org.apache.karaf.shell.impl.action.osgi.CommandExtender] - org.openhab.binding.smaenergymeter (271): Not an extended bundle or destruction of extension already finished
2024-10-07 22:17:09.244 [DEBUG] [org.apache.karaf.shell.impl.action.osgi.CommandExtender] - org.openhab.binding.smaenergymeter (271): Starting destruction process
2024-10-07 22:17:09.246 [DEBUG] [org.apache.karaf.shell.impl.action.osgi.CommandExtender] - org.openhab.binding.smaenergymeter (271): Not an extended bundle or destruction of extension already finished
2024-10-07 22:17:09.274 [WARN ] [n.ThreadPoolManager$UnstoppableScheduledExecutorService] - shutdownNow() invoked on a shared thread pool 'OH-binding-smaenergymeter-listener'. This is a bug, please submit a bug report
java.lang.IllegalStateException: null
        at org.openhab.core.common.ThreadPoolManager$UnstoppableExecutorService.shutdownNow(ThreadPoolManager.java:242) ~[?:?]
        at org.openhab.binding.smaenergymeter.internal.packet.DefaultPacketListenerRegistry.shutdown(DefaultPacketListenerRegistry.java:68) ~[?:?]
        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.invoke(BaseMethod.java:531) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) ~[?:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) ~[?:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:421) ~[?:?]
        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) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleRefPair.ungetServiceObjects(SingleRefPair.java:74) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$AbstractCustomizer.ungetService(DependencyManager.java:231) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.close(DependencyManager.java:1426) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.deactivate(DependencyManager.java:1568) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateDependencyManagers(AbstractComponentManager.java:1280) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:854) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:825) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:589) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:722) [bundleFile:?]
        at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:492) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:652) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator.access$300(Activator.java:74) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:490) [bundleFile:?]
        at org.apache.felix.scr.impl.AbstractExtender$1.run(AbstractExtender.java:216) [bundleFile:?]
        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) [bundleFile:?]
        at org.apache.felix.scr.impl.AbstractExtender.bundleChanged(AbstractExtender.java:132) [bundleFile:?]
        at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:255) [bundleFile:?]
        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.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:472) [org.eclipse.osgi-3.18.0.jar:?]
        at org.apache.karaf.bundle.command.Restart.doExecute(Restart.java:44) [bundleFile:?]
        at org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:55) [bundleFile:?]
        at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:88) [bundleFile:4.4.6]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:68) [bundleFile:4.4.6]
        at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:86) [bundleFile:4.4.6]
        at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:599) [bundleFile:4.4.6]
        at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:526) [bundleFile:4.4.6]
        at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:415) [bundleFile:4.4.6]
        at org.apache.felix.gogo.runtime.Pipe.doCall(Pipe.java:416) [bundleFile:4.4.6]
        at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:229) [bundleFile:4.4.6]
        at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:59) [bundleFile:4.4.6]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
        at java.lang.Thread.run(Thread.java:840) [?:?]