openhab / openhab-addons

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

[keba] item "maxpresetcurrent" is not able to update since update to openHAB version 4 #15876

Closed rose78ch closed 11 months ago

rose78ch commented 11 months ago

Expected Behavior

Changes in item maxpresetcurrent are transferred to the KEBA wallbox and the charging power is changed accordingly.

Current Behavior

We set the value of the item on a sitemap or in a rule to 16 A but the value will not update. See the attached log file. keba_log.log

Additional information

We migrated from openHAB version 3.4.4 to version 4.0.4. Our openHAB instance runs on a Raspberry PI 4, installed with openhabian. Before the migration, openHAB was able to update the item maxpresetcurrent of our KEBA wallbox. So we were able to load surplus solar power into our EV. Since the upgrade, openHAB does no longer update the value current on our wallbox, it only reads the values from the keba-wallbox. This problem occurs also in all openhab versions 4.x installed with docker-images on Synology NAS and it works in all openhab 3.x versions with docker-images on Synology NAS.

Described workaround in issue-15728 does not help in our case.

This issue has been mentioned on openHAB Community: https://community.openhab.org/t/keba-binding-does-not-update-current-value-on-wallbox-with-openhab-4-0-1/148365/4

rose78ch commented 11 months ago

after change the refresh interval from 60 to 10 this error occurs:

2023-11-12 16:03:24.237 [ERROR] [st.core.internal.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/keba:kecontact:f347f11314/config' java.lang.IllegalArgumentException: Cache expire time must be greater than 0 at org.openhab.core.cache.ExpiringCache.<init>(ExpiringCache.java:50) ~[?:?] at org.openhab.core.cache.ExpiringCache.<init>(ExpiringCache.java:63) ~[?:?] at org.openhab.core.cache.ExpiringCacheMap.put(ExpiringCacheMap.java:73) ~[?:?] at org.openhab.binding.keba.internal.handler.KeContactHandler.initialize(KeContactHandler.java:111) ~[?:?] at org.openhab.core.thing.binding.BaseThingHandler.handleConfigurationUpdate(BaseThingHandler.java:110) ~[?:?] at org.openhab.core.thing.internal.ThingRegistryImpl.updateConfiguration(ThingRegistryImpl.java:94) ~[?:?] at org.openhab.core.io.rest.core.internal.thing.ThingResource.updateConfiguration(ThingResource.java:542) ~[?:?] 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.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.4.5] at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.4.5] at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.4.5] at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.4.5] at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.4.5] at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.4.5] at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5] at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.5] at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.5] at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.5] at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.5] at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.5] at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.5] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.5] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:234) ~[bundleFile:3.4.5] at javax.servlet.http.HttpServlet.service(HttpServlet.java:520) ~[bundleFile:4.0.4] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.5] at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[bundleFile:?] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[bundleFile:9.4.50.v20221201] at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:100) ~[bundleFile:?] at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:310) ~[bundleFile:?] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.50.v20221201] at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[bundleFile:?] at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[bundleFile:9.4.50.v20221201] at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[bundleFile:9.4.50.v20221201] at java.lang.Thread.run(Thread.java:840) ~[?:?] 2023-11-12 16:03:25.757 [INFO ] [nternal.handler.KeContactTransceiver] - Listening for incoming data on /0.0.0.0:7090

rose78ch commented 11 months ago

@maihacke & @kaikreuzer do you have an idea how this can be solved?

openhab-bot commented 11 months ago

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/keba-binding-does-not-update-current-value-on-wallbox-with-openhab-4-0-1/148365/8

maihacke commented 11 months ago

I'm not sure what the problem is here. The log shows, that the setting for maxpresetuser was accepted by the box (curr user):

2023-11-10 19:27:57.377 [DEBUG] [nternal.handler.KeContactTransceiver] - Received {
"ID": "2",
"State": 1,
"Error1": 0,
"Error2": 0,
"Plug": 3,
"AuthON": 0,
"Authreq": 0,
"Enable sys": 1,
"Enable user": 1,
"Max curr": 0,
"Max curr %": 1000,
"Curr HW": 16000,
"Curr user": 6635,
"Curr FS": 0,
"Tmo FS": 0,
"Curr timer": 6635,
"Tmo CT": 0,
"Setenergy": 0,
"Output": 0,
"Input": 0,
"Serial": "19863649",
"Sec": 8394023
}
maihacke commented 11 months ago

There might be a problem with cache initialization, but that should not block the curr user setting:

KeContactHandler.java

                cache = new ExpiringCacheMap<>(Math.max(refreshInterval - 5, 0) * 1000);

Error log says that cache expiry must be greater 0, that Math.max may produce 0. If refreshinterval is <= 5. Why this exception occurs with an interval of 10 (according to bug description) is unclear to me.

rose78ch commented 11 months ago

I'm not sure what the problem is here. The log shows, that the setting for maxpresetuser was accepted by the box (curr user):

2023-11-10 19:27:57.377 [DEBUG] [nternal.handler.KeContactTransceiver] - Received {
"ID": "2",
"State": 1,
"Error1": 0,
"Error2": 0,
"Plug": 3,
"AuthON": 0,
"Authreq": 0,
"Enable sys": 1,
"Enable user": 1,
"Max curr": 0,
"Max curr %": 1000,
"Curr HW": 16000,
"Curr user": 6635,
"Curr FS": 0,
"Tmo FS": 0,
"Curr timer": 6635,
"Tmo CT": 0,
"Setenergy": 0,
"Output": 0,
"Input": 0,
"Serial": "19863649",
"Sec": 8394023
}

The value in "curr user" is wrong. It should contain the value 6000 and not 6635. We set the value in a rule when Item ChargeMode changed or Item Keba_VehiclePlugged changed then if ((ChargeMode.state as Number).intValue == 1) { Keba_Switch.sendCommand(ON) Keba_CurrentRangeA.sendCommand((6).intValue)

The item Keba_CurrentRangeA is defined as number type in the keba binding.

If we adjust the rule and set the value via the modbus tcp binding, the value in curr user is set correctly to 6000 in the wall box. new rule: when Item ChargeMode changed or Item Keba_VehiclePlugged changed then if ((ChargeMode.state as Number).intValue == 1) { Keba_Switch.sendCommand(ON) Modbus_Keba_Current.sendCommand(6000)

The item Modbus_Keba_Current is defined as number type in the modbus tcp binding with write address 5400.

maihacke commented 11 months ago

From your item name I assume you are setting the maxpresetcurrentrange channel. So your value is interpreted as percentage value of max system current. If you want to set a specific max current in mA you better use the maxpresetcurrent channel.

rose78ch commented 11 months ago

The item is linked to the channel "maxpresetcurrent (Number:ElectricCurrent)":

image

maihacke commented 11 months ago

From my understanding you are sending the value 6 to this channel. The minimum value is 6000. In the binding the following is implemented:

                transceiver.send("curr " + Math.min(Math.max(6000, value.intValue()), maxSystemCurrent), this);

Does this help?

rose78ch commented 11 months ago

Unfortunately this doesn't help. I created the following rules:

rule Rule_Test_keba_change_ChargeMode
when 
    Item ChargeMode changed
then
    if ((ChargeMode.state as Number).intValue == 1) {
        Keba_CurrentRangeA.sendCommand((7000).intValue)
        logInfo("log","Charge mode = manual / set keba maxpresetcurrent manual to: 7000")
    }
end

rule Rule_Test_keba_change_CurrentRangeA
when
    Item Keba_CurrentRangeA changed
then
    {
        logInfo("log","keba maxpresetcurrent automatically changed to: "  + ((Keba_CurrentRangeA.state as Number).intValue))
    }
end

This is the log output:

2023-12-07 21:09:37.626 [INFO ] [org.openhab.core.model.script.log ] - Charge mode = manual / set keba maxpresetcurrent manual to: 7000 2023-12-07 21:09:37.636 [INFO ] [org.openhab.core.model.script.log ] - keba maxpresetcurrent automatically changed to: 7000 2023-12-07 21:09:47.893 [INFO ] [org.openhab.core.model.script.log ] - keba maxpresetcurrent automatically changed to: 6

First the value 7000 is adopted, then 10 seconds later it is automatically adjusted to 6.

maihacke commented 11 months ago

I think there are problems with the unit conversion. I tried to send values of "6 A", "7 A" to the item. That works. My Item is defined as Number:ElectricCurrent. Yours at Number:Point. This could also lead to problems. Please try to change that and change the rule to:

    Keba_CurrentRangeA.sendCommand("7 A")

Also logs with DEBUG enabled for "org.openhab.binding.keba" would be helpful.

rose78ch commented 11 months ago

The rules work if the item is defined with Number:ElectricCurrent.

rule Rule_Test_keba_change_ChargeMode
when 
    Item ChargeMode changed
then
    if (ChargeMode.state == 1) {
        Keba_CurrentRangeA.sendCommand(7)
    }
end

rule Rule_Test_keba_Plus1A
when
    Time cron "0 * * * * ? *"
then
    if ((Keba_CurrentRangeA.state as Number) < 10) 
    {
        Keba_CurrentRangeA.sendCommand((Keba_CurrentRangeA.state as Number) + 1)
    }
end

Why does the item have to be defined with Number:ElectricCurrent in openhab version 4? This was not necessary with version 3. I have always defined all items in all Things (not just keba) with Number:Point. This gives me flexibility in the rules and I don't have to worry about converting the values ​​to Int, decimal or number.

maihacke commented 11 months ago

OH4 introduced a new system for units of measurement (https://github.com/openhab/openhab-distro/releases/tag/4.0.0#breaking-changes-that-require-manual-interaction-after-the-upgrade).

Maybe there is a simpler version than including the unit in the command string. I personally found this variant working for my rules and didn‘t investigate further if a simpler solution exists- but it might be worth a try.

rose78ch commented 11 months ago

My rule also works without the unit "A" in the sendCommand: Keba_CurrentRangeA.sendCommand(7)