Hi, I have an issue with my homematic devices after upgrading to Openhab 2.3.
My configuration:
Raspberry 3 with HM-MOD-RPI-PCB
openHAB 2.3.0-1 (Release Build)
Homegear (version 0.7.20-1863) on the same raspberry
Behaviour:
In PaperUI all things are online but commands are not executed. I see in the logs that there seems to be a communication problem, that there is no answer from the devices.
The configuration of the Bridge was not changed. Gateway and network call back are set to the IP of the raspberry.
Here are my logs. As I am not sure what an expert would look at I have copied a bigger part of the logs in here.
Like always. Any kind of help or hints would be highly appreciated. I did a lot of reading and did checked my configurations but I am stuck now.
Openhab.log:
2018-06-24 11:52:27.445 [ERROR] [ematic.handler.HomematicThingHandler] - -100 No answer from device. (sending setValue()
OEQ0022366:1
STATE
false
)
java.io.IOException: -100 No answer from device. (sending setValue()
OEQ0022366:1
STATE
false
)
at org.openhab.binding.homematic.internal.communicator.parser.RpcResponseParser.parse(RpcResponseParser.java:47) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:78) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:90) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:66) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.setDatapointValue(RpcClient.java:298) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway$1.execute(AbstractHomematicGateway.java:672) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.misc.DelayedExecuter.start(DelayedExecuter.java:61) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:651) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:630) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.handler.HomematicThingHandler.handleCommand(HomematicThingHandler.java:276) [210:org.openhab.binding.homematic:2.3.0]
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.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
at com.sun.proxy.$Proxy136.handleCommand(Unknown Source) [210:org.openhab.binding.homematic:2.3.0]
at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
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.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
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) [?:?]
2018-06-24 11:53:28.478 [ERROR] [ematic.handler.HomematicThingHandler] - -100 No answer from device. (sending setValue()
OEQ0037312:1
LEVEL
1.0
)
java.io.IOException: -100 No answer from device. (sending setValue()
OEQ0037312:1
LEVEL
1.0
)
at org.openhab.binding.homematic.internal.communicator.parser.RpcResponseParser.parse(RpcResponseParser.java:47) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:78) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:90) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:66) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.setDatapointValue(RpcClient.java:298) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway$1.execute(AbstractHomematicGateway.java:672) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.misc.DelayedExecuter.start(DelayedExecuter.java:61) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:651) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.sendDatapoint(AbstractHomematicGateway.java:630) [210:org.openhab.binding.homematic:2.3.0]
at org.openhab.binding.homematic.handler.HomematicThingHandler.handleCommand(HomematicThingHandler.java:276) [210:org.openhab.binding.homematic:2.3.0]
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.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
at com.sun.proxy.$Proxy136.handleCommand(Unknown Source) [210:org.openhab.binding.homematic:2.3.0]
at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
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.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
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) [?:?]
Homegear.log (Debug Level 5)
06/24/18 11:53:00.921 RPC Server (Port 2001): Response binary:
42696E01000000050000000201
(Array length=1)
{
(Struct length=2)
{
[methodName]
{
(String) event
}
[params]
{
(Array length=4)
{
(String) RF-dcd1d685
(String) CENTRAL
(String) PONG
(String) dcd1d685
}
}
}
}
06/24/18 11:53:00.921 Debug: Calling getFileDescriptor...
06/24/18 11:53:00.921 Debug: Connecting to host 10.0.0.45 on port 9126...
06/24/18 11:53:00.921 Debug: Connected to host 10.0.0.45 on port 9126. Client number is: 27
06/24/18 11:53:00.921 RPC client: Debug: Sending packet: 42696E00000000930000001073797374656D2E6D756C746963616C6C0000000100000100000000010000010100000$
06/24/18 11:53:00.923 RPC client: Debug: Packet received: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:00.923 RPC client: Debug: Received packet from server 10.0.0.45: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:00.923 RPC client: Response was:
(Array length=1)
{
(String) event
}
06/24/18 11:53:15.924 RPC Server (Port 2001): Debug: Packet received: 42696E000000001C0000000470696E670000000100000003000000086463643164363835
06/24/18 11:53:15.931 RPC Server (Port 2001): Info: Client number 22 is calling RPC method: ping (2) Parameters:
(String) dcd1d685
06/24/18 11:53:15.931 RPC Server (Port 2001): Response:
(Boolean) 1
06/24/18 11:53:15.931 RPC client: Debug: Calling RPC method "system.multicall" on server 10.0.0.45.
06/24/18 11:53:15.931 RPC client: Parameters:
06/24/18 11:53:15.931 RPC Server (Port 2001): Response binary:
42696E01000000050000000201
(Array length=1)
{
(Struct length=2)
06/24/18 11:53:00.921 Debug: Connecting to host 10.0.0.45 on port 9126...
06/24/18 11:53:00.921 Debug: Connected to host 10.0.0.45 on port 9126. Client number is: 27
06/24/18 11:53:00.921 RPC client: Debug: Sending packet: 42696E00000000930000001073797374656D2E6D756C746963616C6C0000000100000100000000010000010100000$
06/24/18 11:53:00.923 RPC client: Debug: Packet received: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:00.923 RPC client: Debug: Received packet from server 10.0.0.45: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:00.923 RPC client: Response was:
(Array length=1)
{
(String) event
}
06/24/18 11:53:15.924 RPC Server (Port 2001): Debug: Packet received: 42696E000000001C0000000470696E670000000100000003000000086463643164363835
06/24/18 11:53:15.931 RPC Server (Port 2001): Info: Client number 22 is calling RPC method: ping (2) Parameters:
(String) dcd1d685
06/24/18 11:53:15.931 RPC Server (Port 2001): Response:
(Boolean) 1
06/24/18 11:53:15.931 RPC client: Debug: Calling RPC method "system.multicall" on server 10.0.0.45.
06/24/18 11:53:15.931 RPC client: Parameters:
06/24/18 11:53:15.931 RPC Server (Port 2001): Response binary:
42696E01000000050000000201
(Array length=1)
{
(Struct length=2)
{
[methodName]
{
(String) event
}
[params]
{
(Array length=4)
{
(String) RF-dcd1d685
(String) CENTRAL
(String) PONG
(String) dcd1d685
}
}
}
}
06/24/18 11:53:15.931 Debug: Calling getFileDescriptor...
06/24/18 11:53:15.931 Debug: Connecting to host 10.0.0.45 on port 9126...
06/24/18 11:53:15.932 Debug: Connected to host 10.0.0.45 on port 9126. Client number is: 28
06/24/18 11:53:15.932 RPC client: Debug: Sending packet: 42696E00000000930000001073797374656D2E6D756C746963616C6C0000000100000100000000010000010100000$
06/24/18 11:53:15.935 RPC client: Debug: Packet received: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:15.935 RPC client: Debug: Received packet from server 10.0.0.45: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:15.935 RPC client: Response was:
{
(String) event
}
[params]
{
(Array length=4)
{
(String) RF-dcd1d685
(String) CENTRAL
(String) PONG
(String) dcd1d685
}
}
}
}
06/24/18 11:53:15.931 Debug: Calling getFileDescriptor...
06/24/18 11:53:15.931 Debug: Connecting to host 10.0.0.45 on port 9126...
06/24/18 11:53:15.932 Debug: Connected to host 10.0.0.45 on port 9126. Client number is: 28
06/24/18 11:53:15.932 RPC client: Debug: Sending packet: 42696E00000000930000001073797374656D2E6D756C746963616C6C0000000100000100000000010000010100000$
06/24/18 11:53:15.935 RPC client: Debug: Packet received: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:15.935 RPC client: Debug: Received packet from server 10.0.0.45: 42696E0100000015000001000000000100000003000000056576656E74
06/24/18 11:53:15.935 RPC client: Response was:
(Array length=1)
{
(String) event
}
06/24/18 11:53:23.349 RPC Server (Port 2001): Debug: Packet received: 42696E000000003D0000000873657456616C756500000003000000030000000C4F45513030333733$
06/24/18 11:53:23.350 RPC Server (Port 2001): Info: Client number 22 is calling RPC method: setValue (2) Parameters:
(String) OEQ0037312:1
(String) LEVEL
(Float) 1
06/24/18 11:53:23.351 Module HomeMatic BidCoS: Debug: LEVEL of peer 1 with serial number OEQ0037312:1 was set to C8.
06/24/18 11:53:23.352 Warning: !!!Not!!! sending packet, because init sequence is not complete: 0BE2A011FD491F54AF110301
06/24/18 11:53:25.906 RPC Server (Port 2001): Response:
(Struct length=2)
{
[faultCode]
{
(Integer) -100
}
[faultString]
{
(String) No answer from device.
}
}
06/24/18 11:53:25.907 RPC Server (Port 2001): Response binary:
(String) event
}
06/24/18 11:53:23.349 RPC Server (Port 2001): Debug: Packet received: 42696E000000003D0000000873657456616C756500000003000000030000000C4F45513030333733$
06/24/18 11:53:23.350 RPC Server (Port 2001): Info: Client number 22 is calling RPC method: setValue (2) Parameters:
(String) OEQ0037312:1
(String) LEVEL
(Float) 1
06/24/18 11:53:23.351 Module HomeMatic BidCoS: Debug: LEVEL of peer 1 with serial number OEQ0037312:1 was set to C8.
06/24/18 11:53:23.352 Warning: !!!Not!!! sending packet, because init sequence is not complete: 0BE2A011FD491F54AF110301
06/24/18 11:53:25.906 RPC Server (Port 2001): Response:
(Struct length=2)
{
[faultCode]
{
(Integer) -100
}
[faultString]
{
(String) No answer from device.
}
}
06/24/18 11:53:25.907 RPC Server (Port 2001): Response binary:
42696EFF0000004A0000010100000002000000096661756C74436F646500000001FFFFFF9C0000000B6661756C74537472696E6700000003000000164E6F20616E737765722066726F6D20$
06/24/18 11:53:25.916 RPC Server (Port 2001): Debug: Connection to client number 22 closed (3).
06/24/18 11:53:25.917 RPC Server (Port 2001): Info: Connection from ::ffff:10.0.0.45:37344 accepted. Client number: 29
06/24/18 11:53:25.917 RPC Server (Port 2001): Info: RPC server client id for client number 29 is: 5
06/24/18 11:53:25.919 RPC Server (Port 2001): Listening for incoming packets from client number 29.
06/24/18 11:53:25.919 RPC Server (Port 2001): Debug: Packet received: 42696E000000003D0000000873657456616C756500000003000000030000000C4F45513030333733$
06/24/18 11:53:25.919 RPC Server (Port 2001): Info: Client number 29 is calling RPC method: setValue (2) Parameters:
(String) OEQ0037312:1
(String) LEVEL
(Float) 1
06/24/18 11:53:25.920 Module HomeMatic BidCoS: Debug: LEVEL of peer 1 with serial number OEQ0037312:1 was set to C8.
06/24/18 11:53:25.947 UPnP Server: Debug: Discovery packet received from 239.255.255.250:1900
06/24/18 11:53:25.968 Debug: Sleeping 2710ms before sending response.
06/24/18 11:53:28.474 RPC Server (Port 2001): Response:
(Struct length=2)
{
[faultCode]
{
(Integer) -100
}
[faultString]
{
(String) No answer from device.
}