openHAB, Homegear and Homematic HM-CFG-LAN

[Jan-Piet Mens]

Good afternoon,

I'm trying to get openHAB v1.6.2 (or 1.7.0 snapshot) to talk to a
homematic switch connected to a HM-CFG-LAN adapter. The LAN adapter can
talk to the switch (I've tested with it's Windows Web interface).

By what I've been able to determine so far, openHAB won't do that out of
the box with a binding, so I have to use Homegear as "middleware". I've
configured the AES key (lanKey) in homegear's physicalinterfaces.conf,
invented a new rfKey in the same, and launched Homegear which appears to
'talk' to the HM-CFG-LAN (shown in homegear.log below).

When launching openHAB with `homematic:host=10.0.69.186' configured as
the address of the homegear box, and a single Item which has the address
of the wall plug

Switch SD "Test-Steckdose" {homematic="address=LEQ1068578, channel=1, parameter=STATE"}

I get the following in openHAB:

2015-03-27 18:45:37.261 [DEBUG] [o.b.h.i.bus.HomematicActivator] - Homematic binding has been started.
2015-03-27 18:45:37.291 [DEBUG] [omematicGenericBindingProvider] - Adding item SD with DatapointConfig[address=LEQ1068578,channel=1,parameter=STATE]
2015-03-27 18:45:37.303 [WARN ] [h.i.util.LocalNetworkInterface] - Found multiple local interfaces! Replacing 172.16.153.1 with 172.16.4.1
2015-03-27 18:45:37.304 [WARN ] [h.i.util.LocalNetworkInterface] - Found multiple local interfaces! Replacing 172.16.4.1 with 192.168.1.207
2015-03-27 18:45:37.304 [WARN ] [h.i.util.LocalNetworkInterface] - Found multiple local interfaces! Replacing 192.168.1.207 with 10.0.69.162
2015-03-27 18:45:37.304 [INFO ] [o.o.b.h.i.bus.HomematicBinding] - HomematicConfig[host=10.0.69.186,callbackHost=10.0.69.162,callbackPort=9123,aliveInterval=300]
2015-03-27 18:45:37.304 [INFO ] [.b.h.i.c.HomematicCommunicator] - Starting Homematic communicator
2015-03-27 18:45:37.305 [DEBUG] [.h.i.communicator.ItemDisabler] - Starting ItemDisabler
2015-03-27 18:45:37.315 [INFO ] [.b.h.i.c.HomematicCommunicator] - Homematic ServerId[name=Homegear,version=0.5.24]
2015-03-27 18:45:37.317 [INFO ] [.b.h.i.c.client.HomegearClient] - Starting HomegearClient
2015-03-27 18:45:37.317 [DEBUG] [.o.b.h.i.c.client.BinRpcClient] - Starting BinRpcClient
2015-03-27 18:45:37.318 [INFO ] [b.h.i.communicator.StateHolder] - Loading Homematic datapoints
2015-03-27 18:45:37.319 [INFO ] [.service.AbstractActiveService] - Exec Refresh Service has been started
2015-03-27 18:45:37.329 [INFO ] [b.h.i.communicator.StateHolder] - Finished loading 0 Homematic datapoints
2015-03-27 18:45:37.330 [INFO ] [b.h.i.communicator.StateHolder] - Loading Homematic Server variables
2015-03-27 18:45:37.334 [INFO ] [b.h.i.communicator.StateHolder] - Finished loading 0 Homematic server variables
2015-03-27 18:45:37.334 [INFO ] [b.h.i.c.s.BinRpcCallbackServer] - Starting BinRpcCallbackServer at port 9123
2015-03-27 18:45:37.342 [INFO ] [.b.h.i.c.HomematicCommunicator] - Scheduling one datapoint reload job in 60 seconds
2015-03-27 18:45:37.343 [INFO ] [.service.AbstractActiveService] - Homematic server keep alive thread has been started
2015-03-27 18:45:40.345 [WARN ] [.b.h.i.c.HomematicCommunicator] - Can't find DatapointConfig[address=LEQ1068578,channel=1,parameter=STATE], value is not published to openHAB!

I can see (from homegear's log) that OpenHAB is talking to it (which
means the IP addresses are correct), and it appears to me that Homegear
is talking to the LAN adapter. I've verified the AES keys (Homegear
matches LAN adapter).

What am I missing?

Thanks,

-JP


homegear.log:

03/27/15 18:44:31.286 Debug: Loading family modules
03/27/15 18:44:31.286 Info: Loading family module mod_philipshue.so
03/27/15 18:44:31.288 Module Philips hue: Debug: Loading module...
03/27/15 18:44:31.288 Info: Loading family module mod_homematicbidcos.so
03/27/15 18:44:31.292 Module HomeMatic BidCoS: Debug: Loading module...
03/27/15 18:44:31.292 Info: Loading family module mod_insteon.so
03/27/15 18:44:31.295 Module INSTEON: Debug: Loading module...
03/27/15 18:44:31.295 Info: Loading family module mod_max.so
03/27/15 18:44:31.298 Module MAX: Debug: Loading module...
03/27/15 18:44:31.298 Info: Loading family module mod_homematicwired.so
03/27/15 18:44:31.300 Module HomeMatic Wired: Debug: Loading module...
03/27/15 18:44:31.300 Info: Loading family module mod_miscellaneous.so
03/27/15 18:44:31.301 Module Miscellaneous: Debug: Loading module...
03/27/15 18:44:31.308 Debug: Reading config for physical device family HomeMatic BidCoS
03/27/15 18:44:31.308 Debug: id of family HomeMatic BidCoS set to My-HM-CFG-LAN
03/27/15 18:44:31.309 Debug: default of family HomeMatic BidCoS set to 1
03/27/15 18:44:31.309 Debug: deviceType of family HomeMatic BidCoS set to hmcfglan
03/27/15 18:44:31.309 Debug: Host of family HomeMatic BidCoS set to 10.0.69.115
03/27/15 18:44:31.309 Debug: Port of family HomeMatic BidCoS set to 1000
03/27/15 18:44:31.309 Debug: LANKey of family HomeMatic BidCoS set to BC638FBC7887577007C2F93019B40A15
03/27/15 18:44:31.309 Debug: RFKey of family HomeMatic BidCoS set to 0102030405060708090A0B0C0D0E0F00
03/27/15 18:44:31.309 Debug: CurrentRFKeyIndex of family HomeMatic BidCoS set to 1
03/27/15 18:44:31.309 Debug: responseDelay of family HomeMatic BidCoS set to 60
03/27/15 18:44:31.309 Module HomeMatic BidCoS: Debug: Creating physical device. Type defined in physicalinterfaces.conf is: hmcfglan
03/27/15 18:44:31.309 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Enabling AES encryption for communication with HM-CFG-LAN.
03/27/15 18:44:31.309 Initializing database...
03/27/15 18:44:31.310 Initializing family controller...
03/27/15 18:44:31.310 Module HomeMatic BidCoS: Loading XML RPC devices...
03/27/15 18:44:31.310 Loading XML RPC device /etc/homegear/devices/0/rf_dim_1tconf_644.xml
...
03/27/15 18:44:31.443 Info: Not initializing device family HomeMatic Wired, because no physical interface was found.
03/27/15 18:44:31.443 Info: Not initializing device family INSTEON, because no physical interface was found.
03/27/15 18:44:31.443 Info: Not initializing device family MAX!, because no physical interface was found.
03/27/15 18:44:31.443 Info: Not initializing device family Philips hue, because no physical interface was found.
03/27/15 18:44:31.443 Module Miscellaneous: Loading XML RPC devices...
03/27/15 18:44:31.443 Loading XML RPC device /etc/homegear/devices/254/Template.xml
03/27/15 18:44:31.444 Loading devices...
03/27/15 18:44:31.444 Module HomeMatic BidCoS: Loading HomeMatic BidCoS device 1
03/27/15 18:44:31.445 Module HomeMatic BidCoS: Loading HomeMatic BidCoS device 2
03/27/15 18:44:31.445 Module Miscellaneous: Loading Miscellaneous device 3
03/27/15 18:44:31.445 Start listening for packets...
03/27/15 18:44:31.445 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Connecting to HM-CFG-LAN with hostname 10.0.69.115 on port 1000...
03/27/15 18:44:31.446 Debug: Calling getFileDescriptor...
03/27/15 18:44:31.446 Info: Connecting to host 10.0.69.115 on port 1000...
03/27/15 18:44:31.446 Debug: Thread priority successfully set to: 45
03/27/15 18:44:31.446 Initializing RPC client...
03/27/15 18:44:31.446 Starting XML RPC server RPCServer1 listening on 0.0.0.0:2001...
03/27/15 18:44:31.447 Starting XML RPC server RPCServer2 listening on 0.0.0.0:2002, SSL enabled...
03/27/15 18:44:31.450 Starting XML RPC server RPCServer3 listening on 0.0.0.0:2003, SSL enabled, authentification enabled...
03/27/15 18:44:31.453 Starting CLI server...
03/27/15 18:44:31.453 Initializing event handler...
03/27/15 18:44:31.453 Loading events...
03/27/15 18:44:31.453 Startup complete.
03/27/15 18:44:31.454 RPC Server (Port 2001): Info: RPC Server started listening on address 0.0.0.0 and port 2001
03/27/15 18:44:31.454 RPC Server (Port 2003): Info: RPC Server started listening on address 0.0.0.0 and port 2003
03/27/15 18:44:31.454 RPC Server (Port 2002): Info: RPC Server started listening on address 0.0.0.0 and port 2002
03/27/15 18:44:46.454 Debug: Calling getFileDescriptor...
03/27/15 18:44:46.455 Info: Connecting to host 10.0.69.115 on port 1000...
03/27/15 18:45:01.460 Debug: Calling getFileDescriptor...
03/27/15 18:45:01.460 Info: Connecting to host 10.0.69.115 on port 1000...
03/27/15 18:45:16.466 Debug: Calling getFileDescriptor...
03/27/15 18:45:16.466 Info: Connecting to host 10.0.69.115 on port 1000...
03/27/15 18:45:31.472 Debug: Calling getFileDescriptor...
03/27/15 18:45:31.472 Info: Connecting to host 10.0.69.115 on port 1000...
03/27/15 18:45:37.394 RPC Server (Port 2001): Info: Connection from 10.0.69.162:64285 accepted. Client number: 30
03/27/15 18:45:37.395 RPC Server (Port 2001): Listening for incoming packets from client number 30.
03/27/15 18:45:37.395 RPC Server (Port 2001): Debug: Packet received: 42696E000000002D000000146765744465766963654465736372697074696F6E000000010000000300000009426964436F532D5246
03/27/15 18:45:37.395 RPC Server (Port 2001): Receiving binary rpc packet with size: 45
03/27/15 18:45:37.395 RPC Server (Port 2001): Info: Client number 30 is calling RPC method: getDeviceDescription Parameters:
(String) BidCoS-RF
03/27/15 18:45:37.395 RPC Server (Port 2001): Response:
(Struct length=2)
{
[FIRMWARE]
{
(String) 0.5.24
}
[TYPE]
{
(String) Homegear
}
}
03/27/15 18:45:37.396 RPC Server (Port 2001): Response binary:
42696E010000003A0000010100000002000000084649524D574152450000000300000006302E352E323400000004545950450000000300000008486F6D6567656172
03/27/15 18:45:37.398 Debug: ... data size is 66
03/27/15 18:45:37.399 RPC Server (Port 2001): Info: Connection to client number 30 closed (3).
03/27/15 18:45:37.403 RPC Server (Port 2001): Info: Connection from 10.0.69.162:64286 accepted. Client number: 31
03/27/15 18:45:37.404 RPC Server (Port 2001): Listening for incoming packets from client number 31.
03/27/15 18:45:37.404 RPC Server (Port 2001): Debug: Packet received: 42696E00000000190000000C676574416C6C56616C756573000000010000000201
03/27/15 18:45:37.404 RPC Server (Port 2001): Receiving binary rpc packet with size: 25
03/27/15 18:45:37.404 RPC Server (Port 2001): Info: Client number 31 is calling RPC method: getAllValues Parameters:
(Boolean) 1
03/27/15 18:45:37.410 RPC Server (Port 2001): Response:
(Array length=0)
{
}
03/27/15 18:45:37.411 RPC Server (Port 2001): Response binary:
42696E01000000080000010000000000
03/27/15 18:45:37.413 Debug: ... data size is 16
03/27/15 18:45:37.413 RPC Server (Port 2001): Info: Connection to client number 31 closed (3).
03/27/15 18:45:37.414 RPC Server (Port 2001): Info: Connection from 10.0.69.162:64287 accepted. Client number: 32
03/27/15 18:45:37.414 RPC Server (Port 2001): Listening for incoming packets from client number 32.
03/27/15 18:45:37.415 RPC Server (Port 2001): Debug: Packet received: 42696E000000001D00000015676574416C6C53797374656D5661726961626C657300000000
03/27/15 18:45:37.415 RPC Server (Port 2001): Receiving binary rpc packet with size: 29
03/27/15 18:45:37.415 RPC Server (Port 2001): Info: Client number 32 is calling RPC method: getAllSystemVariables Parameters:
03/27/15 18:45:37.415 RPC Server (Port 2001): Response:
(Struct length=0)
{
}
03/27/15 18:45:37.415 RPC Server (Port 2001): Response binary:
42696E01000000080000010100000000
03/27/15 18:45:37.417 Debug: ... data size is 16
03/27/15 18:45:37.418 RPC Server (Port 2001): Info: Connection to client number 32 closed (3).
03/27/15 18:45:37.421 RPC Server (Port 2001): Info: Connection from 10.0.69.162:64288 accepted. Client number: 33
03/27/15 18:45:37.421 RPC Server (Port 2001): Listening for incoming packets from client number 33.
03/27/15 18:45:37.422 RPC Server (Port 2001): Debug: Packet received: 42696E000000003D00000004696E697400000002000000030000001962696E6172793A2F2F31302E302E36392E3136323A393132330000000300000008486F6D6567656172
03/27/15 18:45:37.422 RPC Server (Port 2001): Receiving binary rpc packet with size: 61
03/27/15 18:45:37.422 RPC Server (Port 2001): Info: Client number 33 is calling RPC method: init Parameters:
(String) binary://10.0.69.162:9123
(String) Homegear
03/27/15 18:45:37.422 RPC Server (Port 2001): Response:
(void)
03/27/15 18:45:37.422 RPC Server (Port 2001): Response binary:
42696E01000000080000000300000000
03/27/15 18:45:37.425 Debug: ... data size is 16
03/27/15 18:45:37.426 RPC Server (Port 2001): Info: Connection to client number 33 closed (3).
03/27/15 18:45:46.477 Debug: Calling getFileDescriptor...
03/27/15 18:45:46.477 Info: Connecting to host 10.0.69.115 on port 1000...
03/27/15 18:45:47.422 Info: Calling XML RPC method "system.listMethods" on server binary://10.0.69.162 and port 9123.
03/27/15 18:45:47.422 Parameters:
(String) Homegear
03/27/15 18:45:47.422 Debug: Calling getFileDescriptor...
03/27/15 18:45:47.422 Info: Connecting to host 10.0.69.162 on port 9123...
03/27/15 18:45:47.423 Info: Connected to host 10.0.69.162 on port 9123. Client number is: 39
03/27/15 18:45:47.423 Sending packet: 42696E000000002A0000001273797374656D2E6C6973744D6574686F6473000000010000000300000008486F6D6567656172
03/27/15 18:45:47.423 Debug: ... data size is 50
03/27/15 18:45:47.425 RPC client receiving binary rpc packet with size: 53. Payload size is: 45
03/27/15 18:45:47.425 Debug: Received packet from server 10.0.69.162 on port 9123: 42696E010000002D0000010000000002000000030000001073797374656D2E6D756C746963616C6C00000003000000056576656E7400
03/27/15 18:45:47.425 Response was:
(Array length=2)
{
(String) system.multicall
(String) event
}
03/27/15 18:45:47.425 Debug: Adding method system.multicall
03/27/15 18:45:47.425 Debug: Adding method event
03/27/15 18:45:53.554 RPC Server (Port 2001): Info: Connection from 10.0.69.162:64293 accepted. Client number: 42
03/27/15 18:45:53.555 RPC Server (Port 2001): Listening for incoming packets from client number 42.
03/27/15 18:45:53.555 RPC Server (Port 2001): Debug: Packet received: 42696E000000002D00000004696E697400000001000000030000001962696E6172793A2F2F31302E302E36392E3136323A39313233
03/27/15 18:45:53.555 RPC Server (Port 2001): Receiving binary rpc packet with size: 45
03/27/15 18:45:53.555 RPC Server (Port 2001): Info: Client number 42 is calling RPC method: init Parameters:
(String) binary://10.0.69.162:9123
03/27/15 18:45:53.555 RPC Server (Port 2001): Response:
(void)
03/27/15 18:45:53.555 RPC Server (Port 2001): Response binary:
42696E01000000080000000300000000
03/27/15 18:45:53.558 Debug: ... data size is 16
03/27/15 18:45:53.558 RPC Server (Port 2001): Info: Connection to client number 42 closed (3).
03/27/15 18:46:01.489 Debug: Calling getFileDescriptor...
03/27/15 18:46:01.489 Info: Connecting to host 10.0.69.115 on port 1000...

[Mitch]

HI J-P,

sometimes I'm facing the same issue:

2015-03-27 18:45:40.345 [WARN ] [.b.h.i.c.HomematicCommunicator] - Can't find DatapointConfig[address=LEQ1068578,channel=1,parameter=STATE], value is not published to openHAB! 

That's always when I got a new device and binding it the first time to homegear.

What helps is executing the following command:

sendCommand(Reload_Datapoints, ON)

That means I have an item:

Switch Reload_Homematic "Reload Homematic" (maintenanceItems)

with a rule:

rule "Reload datapoints manual"
when
    Item Reload_Homematic received update

then
    sendCommand(Reload_Datapoints, ON)
end

Additionally - to be always in sync with homegear I'm using the following rule:

rule "Reload datapoints regularly"
when
    Time cron "0 0 0/12 * * ?"   // every 12 hours
then
    sendCommand(Reload_Datapoints, ON)
end

Perhaps that helps in your case, too

Regards,

Michael

[Jan-Piet Mens]

Michael,

just 4 minutes ago I got it working, but thank you nevertheless. The
reason was: I was pairing my switch to the HM-CFG-LAN (at least that's
what I think I was doing) with the Homematic Web interface.

Only after reading the whole Internet :-) did it dawn on me that I have
to pair the swtich with Homegear. After doing that, the switch works
from openHAB as configured.

Regards,

-JP