Homegear Issue after Openhab 2.3 Update


#1

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. :slight_smile:

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.
  }

#2

You should upgrade to the current homegear, it’s something like 0.7.22 or so. I remember som communication issues with openHAB in some rare cases.


#3

Hi Job. Thanks for the hint. The answer took me some time as I was trying to find out what I am doing wrong in terms of updating/upgrading the existing system. I did several apt-get upgrade and apt-get update but I am stuck at the current version. Would appreciate if you could point me to the right way how to update the system. Thanks a lot.


#4

I managed the update (didn’t know the command apt full-upgrade). I am now on version 0.7.23-1891 and the issue is unfortunately not resolved yet.

Will check if the updates had an impact on the log files.


#5

Issue has been fixed.

I saw this error in the homegear.log
“Setting peer to unreachable, because the queue processing was interrupted.”

#######################################
########### HM-MOD-RPI-PCB  ###########
#######################################

## The device family this interface is for
[HomeMatic Wireless Module for Raspberry Pi]

## Specify an unique id here to identify this device in Homegear
**id = My-HM-MOD-RPI-PCB**

## When default is set to "true" Homegear will assign this device
## to new peers.
`default = true`

## Options: cul, cc1100, coc, cunx, hmcfglan, hmlgw, hm-mod-rpi-pcb, homegeargateway
deviceType = hm-mod-rpi-pcb

device = /dev/ttyAMA0

## Default: responseDelay = 95
## Should be "95" for CUL or COC, "100" for TI CC1101 and "60" for HM-CFG-LAN or HM-LGW
responseDelay = 95

## Default: gpio1 = 0
## "18" for HM-MOD-RPI-PCB
gpio1 = 18

I did some more research in this forum and in a similar thread I saw how a user has configured the homematicbidcos.conf and compared it with my. After uncommenting the bold sections everything is working again.


#6