This page last changed on Nov 07, 2013 by espen.

Hi,

Having moved to a new installation i expected this to be as stable as my previous setup. I have changed from ABB knx ip interface to Gira, but otherwise it is basically the same, with Openremote and Eibnetmux on the same raspberry pi.

If someone has had similar behaviour and have tips on how to solve this, i would love to hear about it

Using OR snapshot 2.1.0 17/06/2013.

When starting OR this can be found in the knx debug log::

INFO 2013-10-20 12:21:14,939 (KNX): KNX IP interface hostname set to '192.168.10.220'
INFO 2013-10-20 12:21:14,943 (KNX): KNX IP interface port set to '3671'
INFO 2013-10-20 12:21:14,946 (KNX): KNX PhysicalBus clazz set to 'org.openremote.controller.protocol.port.DatagramSocketPort'
INFO 2013-10-20 12:21:14,962 (KNX): Scheduled reconnection task
WARN 2013-10-20 12:21:14,970 (KNX): Unknown KNX property '<property name = "name" value = "C_Living_Left_Wall_ON-OFF"/>'.
INFO 2013-10-20 12:21:14,966 (KNX): Trying to create connection
INFO 2013-10-20 12:21:14,975 (KNX): Removing connection
INFO 2013-10-20 12:21:15,003 (KNX): KNX Connection manager resolving local host IP addresses...
INFO 2013-10-20 12:21:15,013 (KNX): Found candidate NIC: name:eth0 (eth0)
INFO 2013-10-20 12:21:15,033 (KNX): Added candidate IP address to set - /192.168.10.220
INFO 2013-10-20 12:21:15,042 (KNX): Skipping loopback interface: name:lo (lo)
DEBUG 2013-10-20 12:21:15,308 (KNX): Creating KNX bus with org.openremote.controller.protocol.port.DatagramSocketPort
INFO 2013-10-20 12:21:15,458 (KNX): Found a KNX IP interface at /192.168.10.220:3671
INFO 2013-10-20 12:21:15,633 (KNX): Connection created for KNX IP interface at /192.168.10.220:3671
DEBUG 2013-10-20 12:21:15,637 (KNX): Creating KNX bus with org.openremote.controller.protocol.port.DatagramSocketPort
INFO 2013-10-20 12:21:15,642 (KNX): Found a KNX IP interface at /192.168.10.150:3671
INFO 2013-10-20 12:21:15,696 (KNX): Created KNX Command [FRAME] L_Data.req 0.0.0 -> 1/5/27 Data: 0x00 for group address '1/5/27'
INFO 2013-10-20 12:21:15,721 (KNX): Notified with KNX interface status = connected
INFO 2013-10-20 12:21:15,732 (KNX): Connected to KNX-IP interface /192.168.10.220:3671
INFO 2013-10-20 12:21:15,744 (KNX): KNX-IP socket listener IOException
java.net.SocketException: Socket closed
	at java.net.PlainDatagramSocketImpl.receive0(Native Method)
	at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:143)
	at java.net.DatagramSocket.receive(DatagramSocket.java:781)
	at org.openremote.controller.protocol.port.DatagramSocketPort.receive(DatagramSocketPort.java:78)
	at org.openremote.controller.protocol.knx.ip.IpProcessor$PhysicalBusListener.run(IpProcessor.java:82)
WARN 2013-10-20 12:21:15,763 (KNX): KNX-IP socket listener stopped
INFO 2013-10-20 12:21:15,767 (KNX): Stopping connection timer
WARN 2013-10-20 12:21:15,856 (KNX): Unknown KNX property '<property name = "name" value = "CS_Lys_Stue_Vegg_H-ON-OFF"/>'.
INFO 2013-10-20 12:21:15,860 (KNX): Created KNX Command [FRAME] L_Data.req 0.0.0 -> 1/5/28 Data: 0x00 for group address '1/5/28'
DEBUG 2013-10-20 12:21:15,956 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/27 Data: 0x00
DEBUG 2013-10-20 12:21:15,977 (KNX): Polling device status for [FRAME] L_Data.req 0.0.0 -> 1/5/28 Data: 0x00

Problem starts not long after starting OR, with the stacktrace below

INFO 2013-10-20 11:57:50,469 (KNX): Created KNX Command [FRAME] L_Data.req 0.0.0 -> 1/1/27 Data: 0x01 for group address '1/1/27'
WARN 2013-10-20 12:07:41,359 (KNX): Unknown KNX property '<property name = "name" value = "C_Living_Left_Wall_OFF"/>'.
INFO 2013-10-20 12:07:41,361 (KNX): Created KNX Command [FRAME] L_Data.req 0.0.0 -> 1/1/27 Data: 0x00 for group address '1/1/27'
ERROR 2013-10-20 12:07:41,430 (KNX): Service failed
org.openremote.controller.protocol.knx.ip.KnxIpException: Service failed : 39
	at org.openremote.controller.protocol.knx.ip.IpTunnelClient.service(IpTunnelClient.java:93)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.service(KNXIpConnectionManager.java:858)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.send(KNXIpConnectionManager.java:662)
	at org.openremote.controller.protocol.knx.KNXCommand.write(KNXCommand.java:325)
	at org.openremote.controller.protocol.knx.GroupValueWrite.send(GroupValueWrite.java:115)
	at org.openremote.controller.service.impl.ControlCommandServiceImpl.trigger(ControlCommandServiceImpl.java:95)
	at org.openremote.controller.rest.ControlCommandRESTServlet.handleRequest(ControlCommandRESTServlet.java:77)
	at org.openremote.controller.rest.RESTAPI.doPost(RESTAPI.java:159)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.openremote.controller.rest.support.json.JSONCallbackFilter.doFilter(JSONCallbackFilter.java:63)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:78)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:77)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:354)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:724)
INFO 2013-10-20 12:07:41,448 (KNX): KNX-IP socket listener IOException
java.net.SocketException: Socket closed
	at java.net.PlainDatagramSocketImpl.receive0(Native Method)
	at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:143)
	at java.net.DatagramSocket.receive(DatagramSocket.java:781)
	at org.openremote.controller.protocol.port.DatagramSocketPort.receive(DatagramSocketPort.java:78)
	at org.openremote.controller.protocol.knx.ip.IpProcessor$PhysicalBusListener.run(IpProcessor.java:82)
WARN 2013-10-20 12:07:41,450 (KNX): KNX-IP socket listener stopped
INFO 2013-10-20 12:07:41,452 (KNX): Notified with KNX interface status = disconnected
INFO 2013-10-20 12:07:41,453 (KNX): Scheduled reconnection task
INFO 2013-10-20 12:07:41,454 (KNX): Disconnected gracefully from /192.168.10.220:3671
INFO 2013-10-20 12:07:41,455 (KNX): Notified with KNX interface status = disconnected
INFO 2013-10-20 12:07:41,462 (KNX): Trying to create connection
INFO 2013-10-20 12:07:41,462 (KNX): Removing connection
INFO 2013-10-20 12:07:41,463 (KNX): Notified with KNX interface status = disconnected
ERROR 2013-10-20 12:07:41,464 (KNX): Disconnect failed
org.openremote.controller.protocol.knx.ip.KnxIpException: Disconnect failed
	at org.openremote.controller.protocol.knx.ip.IpTunnelClient.disconnect(IpTunnelClient.java:147)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.stop(KNXIpConnectionManager.java:819)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.access$000(KNXIpConnectionManager.java:637)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager.stop(KNXIpConnectionManager.java:210)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$ConnectionTask.removeConnection(KNXIpConnectionManager.java:1004)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$ConnectionTask.run(KNXIpConnectionManager.java:991)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
INFO 2013-10-20 12:07:41,467 (KNX): KNX Connection manager resolving local host IP addresses...
INFO 2013-10-20 12:07:41,469 (KNX): Found candidate NIC: name:eth0 (eth0)
INFO 2013-10-20 12:07:41,470 (KNX): Added candidate IP address to set - /192.168.10.220
INFO 2013-10-20 12:07:41,471 (KNX): Skipping loopback interface: name:lo (lo)
INFO 2013-10-20 12:07:41,479 (KNX): Found a KNX IP interface at /192.168.10.220:3671
INFO 2013-10-20 12:07:41,481 (KNX): Connection created for KNX IP interface at /192.168.10.220:3671
INFO 2013-10-20 12:07:41,485 (KNX): Found a KNX IP interface at /192.168.10.150:3671
INFO 2013-10-20 12:07:41,490 (KNX): Notified with KNX interface status = connected
INFO 2013-10-20 12:07:41,491 (KNX): Connected to KNX-IP interface /192.168.10.220:3671
INFO 2013-10-20 12:07:41,494 (KNX): KNX-IP socket listener IOException
java.net.SocketException: Socket closed
	at java.net.PlainDatagramSocketImpl.receive0(Native Method)
	at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:143)
	at java.net.DatagramSocket.receive(DatagramSocket.java:781)
	at org.openremote.controller.protocol.port.DatagramSocketPort.receive(DatagramSocketPort.java:78)
	at org.openremote.controller.protocol.knx.ip.IpProcessor$PhysicalBusListener.run(IpProcessor.java:82)
WARN 2013-10-20 12:07:41,496 (KNX): KNX-IP socket listener stopped
INFO 2013-10-20 12:07:41,497 (KNX): Stopping connection timer
ERROR 2013-10-20 12:07:41,961 (KNX): Service failed
org.openremote.controller.protocol.knx.ip.KnxIpException: Service failed : 39
	at org.openremote.controller.protocol.knx.ip.IpTunnelClient.service(IpTunnelClient.java:93)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.service(KNXIpConnectionManager.java:858)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.read(KNXIpConnectionManager.java:670)
	at org.openremote.controller.protocol.knx.KNXCommand.read(KNXCommand.java:356)
	at org.openremote.controller.protocol.knx.GroupValueRead.read(GroupValueRead.java:145)
	at org.openremote.controller.model.sensor.Sensor$DeviceReader.read(Sensor.java:682)
	at org.openremote.controller.model.sensor.Sensor$DeviceReader.run(Sensor.java:608)
	at java.lang.Thread.run(Thread.java:724)
INFO 2013-10-20 12:07:41,969 (KNX): KNX-IP socket listener IOException
java.net.SocketException: Socket closed
	at java.net.PlainDatagramSocketImpl.receive0(Native Method)
	at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:143)
	at java.net.DatagramSocket.receive(DatagramSocket.java:781)
	at org.openremote.controller.protocol.port.DatagramSocketPort.receive(DatagramSocketPort.java:78)
	at org.openremote.controller.protocol.knx.ip.IpProcessor$PhysicalBusListener.run(IpProcessor.java:82)
WARN 2013-10-20 12:07:41,971 (KNX): KNX-IP socket listener stopped
INFO 2013-10-20 12:07:41,972 (KNX): Notified with KNX interface status = disconnected
INFO 2013-10-20 12:07:41,974 (KNX): Scheduled reconnection task
INFO 2013-10-20 12:07:41,975 (KNX): Disconnected gracefully from /192.168.10.220:3671
INFO 2013-10-20 12:07:41,975 (KNX): Notified with KNX interface status = disconnected
INFO 2013-10-20 12:07:41,981 (KNX): Trying to create connection
INFO 2013-10-20 12:07:41,982 (KNX): Removing connection
INFO 2013-10-20 12:07:41,983 (KNX): Notified with KNX interface status = disconnected
ERROR 2013-10-20 12:07:41,997 (KNX): Disconnect failed
org.openremote.controller.protocol.knx.ip.KnxIpException: Disconnect failed
	at org.openremote.controller.protocol.knx.ip.IpTunnelClient.disconnect(IpTunnelClient.java:147)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.stop(KNXIpConnectionManager.java:819)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$KNXConnectionImpl.access$000(KNXIpConnectionManager.java:637)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager.stop(KNXIpConnectionManager.java:210)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$ConnectionTask.removeConnection(KNXIpConnectionManager.java:1004)
	at org.openremote.controller.protocol.knx.KNXIpConnectionManager$ConnectionTask.run(KNXIpConnectionManager.java:991)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)

Hey Espen,
I noticed you have two KNX IP interfaces: 192.168.10.220 and 192.168.10.150.
Maybe you can try with only one active, the traces themselves don't mean much to me, sorry.
Cheers
Stijn

Posted by garfield.arbuckle at Oct 22, 2013 15:33

Hi,

One is the Gira ip gateway and the other one is eibnetmux that is connected to the ip gateway, so that is correct. Openremote is configured to connect to eibnetmux on 192.168.10.220

Thanx for your input!

Regards,
Espen

Posted by espen at Oct 22, 2013 18:53

We are handling the error responses extremely poorly and it's something I need to improve a great deal. Digging into the specs, the error response 39 on the connection state response (the UDP 'heart beat') would indicate an error in the KNX connection:

The EIBnet/IP server device detected an error concerning the EIB bus / KNX subsystem connection with the specified ID.

It's unclear why eibnetmux would respond with that error code – are there any logs on the eibnetmux side that would reveal anything out of the ordinary?

Posted by juha at Oct 22, 2013 19:31

Hi Juha, thank you for responding.

I can't really find anything on the eibnetmux side other than suddenly a lot of new connections being established from Openremote when the connection is lost. It seems that when there has been no user interaction or scheduled commands executed for a while, the connection is broken between probably eibnetmux and the ip interface.

According to the eibnetmux site you can mock the ip interface as described:
"...you can also "localhost" or EIBnetmux' ip address and port. This will automatically activate loopback mode with which you do not need a real KNX bus and no IP gateway to test your applications."

When i do this there is no errors at all, and everything is stable over time.

The next step for me is to try with a different ip interface. Used to have ABB before, so ill try to get one of those to se how it behaves in my current setup. The supplier of the Gira interface will be contacting Gira directly to try to find if there are issues with non KNX certified equipment as they had heard about issues with it before in relation to Openremote. It would be very interesting to hear from others with similar setup and with Gira interface, both success and fail.

I will update this thread with the result for later reference.

The following is logged by eibnetmux as Openremote tries to reach the bus again ::

2013/10/23 21:43:32.467 - INF - 45 - Main - My IP address: 127.0.1.1
2013/10/23 21:45:35.639 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:19.647 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:19.984 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:20.538 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:23.510 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:24.102 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:27.039 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:27.647 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:30.573 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:31.175 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:34.107 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:34.713 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:37.641 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:38.263 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:41.175 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:41.789 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:44.709 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:45.322 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:48.242 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:48.855 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:51.777 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:52.392 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:55.309 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:55.926 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:58.844 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220
2013/10/23 22:39:59.460 - INF - 37 - EIBnet/IP Server - Tunnelling connection established with 192.168.10.220

Posted by espen at Oct 23, 2013 22:45

According to the eibnetmux site you can mock the ip interface as described:
"...you can also "localhost" or EIBnetmux' ip address and port. This will automatically activate loopback mode with which you do not need a real KNX bus and no IP gateway to test your applications."

When i do this there is no errors at all, and everything is stable over time.

Ok, thanks for digging into this.

If you discover anything on our side that we can do to help eibnetmux not close the connection to the knx network, please let us know.

Posted by juha at Oct 24, 2013 14:43

Issue resolved. Ill add the solution here in case someone should find it useful.

Seems that the Gira IP interface is a bit on the sensitive side regarding incorrect packages. ABB and Siemens are apparently ignoring superfluous bytes at the end of Eibnetmux's haertbeat request, while the Gira interface dumps the request as invalid and never gives a response back to Eibnetmux, which in turn closes the connection.

As i was just about to turn back the Gira interface for an ABB one, I am very thankful for Urs Zurbuchen taking the time to look into this issue.
Here is the fix he gave me:

In src/eibnetmux/client.c, line 183, replace EIBNETIP_CONNECT_REQUEST with EIBNETIP_CONNECTSTATE_REQUEST

This is the diff:
--- client.c.org        2013-11-05 14:17:17.287019000 +0100
+++ client.c    2013-11-05 14:17:43.200250000 +0100
@@ -180,7 +180,7 @@
     pth_mutex_acquire( &mtxClientInUse, FALSE, NULL );
     clientcon[0].statsPacketsSent++;
     statsTotalSent++;
-    eibNetIpSendControl( EIBNETIP_CLIENT, &clientcon[0], &clientcon[0].hpai, CONNECTIONSTATE_REQUEST, (uint8_t *)request, sizeof( EIBNETIP_CONNECT_REQUEST ));
+    eibNetIpSendControl( EIBNETIP_CLIENT, &clientcon[0], &clientcon[0].hpai, CONNECTIONSTATE_REQUEST, (uint8_t *)request, sizeof( EIBNETIP_CONNECTSTATE_REQUEST ));
     pth_mutex_release( &mtxClientInUse );

     free( request );
Posted by espen at Nov 07, 2013 13:10
Document generated by Confluence on Jun 05, 2016 09:40