search

openhab / openhab-addons

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

KNX Binding 1.x (Version 1.8) not working with Openhab 2.0.0.b1 #631

Closed tbrandstetter closed 8 years ago

tbrandstetter commented 8 years ago

Hi,

I'm relatively new to Openhab and try to use the new Openhab2 beta for my house. Because the Openhab2 binding for KNX is not ready yet I tried the 1.8 version. I can start Openhab2 and the KNX binding also prints out that it should work:

22:20:22.484 [INFO ] [nx.internal.connection.KNXConnection] - Established connection to KNX bus on 192.168.2.7:3671 in mode TUNNEL.
22:21:02.464 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
22:21:02.467 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
22:21:03.443 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8

But it doesn't read values from my items which are configured as:

Number Temperatur_Haus_Wetterstation  "Temperatur [%.1f °C]" <temperature>   (Aussentemperatur) { knx="<9.001:5/4/7" }
Number Windstaerke_Haus_Wetterstation "Windgeschwindigkeit [%.1f m/s]" <temperature> (Windgeschwindigkeit) { knx="<9.001:5/4/8" }

My KNX binding configuration looks like this:

knx:ip=192.168.2.7
knx:type=TUNNEL
knx:port=3671
knx:localIP=192.168.2.244

I'm using an raspberryPI with EIBD connected to an MDT KNX-USB Interface (SCN-USBR.01). What is strange that it's working with Openhab 1.8:

2016-01-16 22:28:17.472 [INFO ] [runtime.busevents             ] - Temperatur_Haus_Wetterstation received command -2.8000000000000003
2016-01-16 22:28:17.562 [INFO ] [runtime.busevents             ] - Windstaerke_Haus_Wetterstation received command 0.8
2016-01-16 22:36:52.686 [INFO ] [runtime.busevents             ] - Windstaerke_Haus_Wetterstation received command 1.3

If you need further information, don't hesitate to contact me.

kgoderis commented 8 years ago

Thomas,

In fact, the KNX 2.0 binding is ready, it is only not in the official repo. I wrote it, and have it running for more than a year wo any problems. If you want to give it a go, you can fetch it via https://github.com/kgoderis/openhab2/tree/knx/addons/binding

tbrandstetter commented 8 years ago

Hi,

I've already tried the 2.0 binding as well, but it's also not working. It connects fine but gives me the message:

Ignoring KNX bus data: couldn't transform to an openHAB type (not supported).

My configuration for the 2.0 binding looked like this:

Bridge knx:ip:ip1 [ ipAddress="192.168.2.7", portNumber=3671, localIp="192.168.2.244", ipConnectionType="TUNNEL", readingPause=50, responseTimeOut=1000, readRetriesLimit=3, autoReconnectPeriod=1 ]
{
  Number : ga_5_4_7 [ address="5/4/7", dpt="9.001", read=true, interval=3600]
}

If you want I can create a new issue for the 2.0 binding as well. We can also try to figure out what the problem is before I open an issue.

kgoderis commented 8 years ago

No, we can check first what is going on. Can you put it to TRACE level logging? Then you will get details as well on the data transformation bits. It is strange, because 9.001 is a supported DPT (Temperature), and it should be a Number channel on the bridge. Have plenty of 9.001's defined in my setup.

That error is given when the type for the incoming data can not be mapped on a java type. In this case, 9.001 should map on a DecimalType. normally, the error statement gives you also the destination GA, as well as a hex dump of the payload of the KNX telegram. You did not copy those over in the msg above....

tbrandstetter commented 8 years ago

I tried it again in trace mode. If I create only a "channel" configuration I get nothing at all (like in the 1.8 knx binding). On my test before I had this mysterious error message I told you - now nothing:

08:48:48.941 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:48:51.380 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
08:48:53.920 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:48:54.841 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:48:55.660 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.5
08:48:55.825 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:48:58.844 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:48:58.847 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:48:59.859 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8

It's getting interesting when I try to use the "things" configuration:

Bridge knx:ip:ip1 [ ipAddress="192.168.2.7", portNumber=3671, localIp="192.168.2.244", ipConnectionType="TUNNEL", readingPause=50, responseTimeOut=1000, readRetriesLimit=3, autoReconnectPeriod=1 ]
{
  Thing ga OutdoorTemperature [ address="5/4/7", dpt="9.001", read=true, interval=3600]
}

With this configuration I now get the same error as with the "channel" configuration:

08:53:47.679 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'knx:ip:ip1' has been added.
08:53:47.691 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from UNINITIALIZED to INITIALIZING
08:53:47.726 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-2] KNXnet/IP Tunneling 192.168.2.7:3671: establish connection from /192.168.2.244:61038 to /192.168.2.7:3671
08:53:47.727 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-2] KNXnet/IP Tunneling 192.168.2.7:3671: wait for connect response from /192.168.2.7:3671 ...
08:53:47.731 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] KNXnet/IP Tunneling 192.168.2.7:3671: using server-assigned data endpoint /192.168.2.7:3671
08:53:47.733 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-2] KNXnet/IP Tunneling 192.168.2.7:3671: connection established
08:53:47.744 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from INITIALIZING to ONLINE
08:53:47.745 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'knx:ga:ip1:OutdoorTemperature' has been added.
08:53:47.747 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ga:ip1:OutdoorTemperature' changed from UNINITIALIZED to INITIALIZING
08:53:47.753 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ga:ip1:OutdoorTemperature' changed from INITIALIZING to ONLINE

08:53:58.865 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:53:58.867 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
08:53:59.800 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8

That's the output from smarthome:things:

knx:ip:ip1 (Type=Bridge, Status=ONLINE, Bridge=null)
knx:ga:ip1:OutdoorTemperature (Type=Thing, Status=ONLINE, Bridge=knx:ip:ip1)

I also created an item for the things channel available:

/* Outdoor Temperatures */
Number OutdoorTemperature       "Temperature [%.1f °C]" <temperature>   { channel="knx:ga:ip1:OutdoorTemperature:string" }

and the status is:

smarthome:status OutdoorTemperature
NULL

So it actually writes never a value to the thing or channel. As I said the knx binding 1.8 works with openhab 1.8 in my environment.

kgoderis commented 8 years ago

In the 2.0 binding there are (because of experimental reasons) two ways to hook up GA's. Either you define a "ga" Thing, or you can define channels on the bridge, like you did in the previous attempt. For my own installation I did everything via the channels on the bridge, except for special Things like the energyswitch (see for example ESH-INF in the source tree). I am a bit puzzled here

Now, in the logs above everything is INFO, not TRACE. You should see stuff like:

2016-01-17 09:21:29 [TRACE] [.k.h.KNXBridgeBaseThingHandler:753 ] - The channel 'knx:ip:ip1:ga_6_1_33' is bound to item 'TechnicalFacilitiesElectricityL2ActivePower' 2016-01-17 09:21:29 [TRACE] [.k.h.KNXBridgeBaseThingHandler:755 ] - Item 'TechnicalFacilitiesElectricityL2ActivePower' has a channel with id 'knx:ip:ip1:ga_6_1_33' 2016-01-17 09:21:29 [TRACE] [.k.h.KNXBridgeBaseThingHandler:770 ] - Processed event (channel='knx:ip:ip1:ga_6_1_33', value='130.0', destination='6/1/33') 2016-01-17 09:21:29 [TRACE] [.o.b.k.i.dpt.KNXCoreTypeMapper:191 ] - toType datapoint DPT = 14.056 2016-01-17 09:21:29 [TRACE] [.o.b.k.i.dpt.KNXCoreTypeMapper:216 ] - toType datapoint getMainNumber = 0 2016-01-17 09:21:29 [TRACE] [.o.b.k.i.dpt.KNXCoreTypeMapper:348 ] - toTypeClass looking for dptId = 14.056

Can you check, preferably with the approach whereby you define Number channels on the ip bridge?

kgoderis commented 8 years ago

Just to make sure, can you add "Channels:"?

Bridge knx:ip:ip1 [ ipAddress="192.168.2.7", portNumber=3671, localIp="192.168.2.244", ipConnectionType="TUNNEL", readingPause=50, responseTimeOut=1000, readRetriesLimit=3, autoReconnectPeriod=1 ] { Channels: Number : ga_5_4_7 [ address="5/4/7", dpt="9.001", read=true, interval=3600] }

tbrandstetter commented 8 years ago

Now I'm getting more and also the error I told before:

09:32:30.349 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'knx:ip:ip1' has been added.
09:32:30.356 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from UNINITIALIZED to INITIALIZING
09:32:30.409 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-3] KNXnet/IP Tunneling 192.168.2.7:3671: establish connection from /192.168.2.244:57392 to /192.168.2.7:3671
09:32:30.411 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-3] KNXnet/IP Tunneling 192.168.2.7:3671: wait for connect response from /192.168.2.7:3671 ...
09:32:30.416 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] KNXnet/IP Tunneling 192.168.2.7:3671: using server-assigned data endpoint /192.168.2.7:3671
09:32:30.418 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-3] KNXnet/IP Tunneling 192.168.2.7:3671: connection established
09:32:30.430 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from INITIALIZING to ONLINE
09:32:30.480 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send message to 5/4/7, wait for confirmation
09:32:30.481 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: cEMI L-Data.req from 0.0.0 to 5/4/7, low priority hop count 6 repeat tpdu 00 00
09:32:30.483 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyChange'
09:32:30.483 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] KNXnet/IP Tunneling 192.168.2.7:3671: sending cEMI frame, wait for cEMI.con, attempt 1
09:32:30.488 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: confirmation of 5/4/7
09:32:30.488 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send to 5/4/7 succeeded
09:32:30.493 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: sent group read request to 5/4/7
09:32:30.584 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'OutdoorTemperature-knx:ga:ip1:OutdoorTemperature:string' has been added.
09:32:31.491 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: timeout waiting for group read response
09:32:31.491 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Cannot read value for datapoint '5/4/7' from KNX bus: timeout waiting for group read response
09:32:31.544 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send message to 5/4/7, wait for confirmation
09:32:31.545 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: cEMI L-Data.req from 0.0.0 to 5/4/7, low priority hop count 6 repeat tpdu 00 00
09:32:31.546 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] KNXnet/IP Tunneling 192.168.2.7:3671: sending cEMI frame, wait for cEMI.con, attempt 1
09:32:31.555 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
09:32:31.561 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: confirmation of 5/4/7
09:32:31.561 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send to 5/4/7 succeeded
09:32:31.561 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Ignoring KNX bus data: couldn't transform to an openHAB type (not supported). Destination='5/4/7', datapoint='command DP 5/4/7 knx:ip:ip1, DPT main 0 id 9.001, low priority', data='0x86B6'
09:32:31.561 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: sent group read request to 5/4/7
09:32:31.567 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Boolean (main type 1) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Boolean controlled (main type 2 loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 3 Bit controlled (main type 3) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 8 Bit unsigned value (main type 5) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 2 octet unsigned value (main type 7) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 2 octet float value (main type 9) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Time (main type 10) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Date (main type 11) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet unsigned value (main type 12) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet signed value (main type 13) loaded
09:32:31.569 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet float value (main type 14) loaded
09:32:31.570 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: String (main type 16) loaded
09:32:31.570 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Scene number (main type 17) loaded
09:32:31.570 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Scene control (main type 18) loaded
09:32:31.570 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Date with time (main type 19) loaded
09:32:31.613 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:32:31.618 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
09:32:31.619 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Ignoring KNX bus data: couldn't transform to an openHAB type (not supported). Destination='5/4/7', datapoint='command DP 5/4/7 knx:ip:ip1, DPT main 0 id 9.001, low priority', data='0x86B6'
kgoderis commented 8 years ago

Thomas, can you add

<logger name="org.openhab.binding.knx" level="TRACE" />

to your logback.xml?

kgoderis commented 8 years ago

Btw, I see that the DPTXlator are loaded by Claimer after the first data arrives. This is a bit strange, did not see that before (I never look at this level of logging), so, the error continues thereafter as well (e.g. some seconds after you the the DPTXlator messages)?

tbrandstetter commented 8 years ago

No, the error messages are gone after the DPTXlator. I have to say that I had problems with the Eclipse build. I had to add the nrjavaserial library directly to the libs in your binding. Furthermore the plugin only works with Openhab also build by Maven as the binding. Maybe you can upload a ready to deploy knx 2.0 binding for Openhab 2.0.0.b1? I created a logback.xml in runtime/etc (copied it from the 1.8 release) but there are no additional TRACE lines, although I've already seen TRACE lines in the log (as you can see below), but not for the knx binding:

09:51:29.219 [INFO ] [.openhab.core.internal.CoreActivator] - openHAB runtime has been started (v2.0.0, build b1).
09:51:29.229 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.things'
09:51:29.309 [TRACE] [ractDeclarativeValueConverterService] - Tried to register value converter for rule 'INT' which is not available in the grammar.
09:51:29.364 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 80 ms
09:51:29.368 [DEBUG] [.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 2ms
09:51:29.377 [DEBUG] [.linking.impl.AbstractCleaningLinker] - doLinkModel took: 9ms
09:51:29.377 [DEBUG] [.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
09:51:29.412 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'knx:ip:ip1' has been added.
09:51:29.416 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from UNINITIALIZED to INITIALIZING
09:51:29.455 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-2] KNXnet/IP Tunneling 192.168.2.7:3671: establish connection from /192.168.2.244:60440 to /192.168.2.7:3671
09:51:29.455 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-2] KNXnet/IP Tunneling 192.168.2.7:3671: wait for connect response from /192.168.2.7:3671 ...
09:51:29.460 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] KNXnet/IP Tunneling 192.168.2.7:3671: using server-assigned data endpoint /192.168.2.7:3671
09:51:29.462 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-2] KNXnet/IP Tunneling 192.168.2.7:3671: connection established
09:51:29.463 [DEBUG] [.www.protocol.http.HttpURLConnection] - sun.net.www.MessageHeader@198c47bc5 pairs: {GET /v1/public/yql?q=SELECT+*+FROM+geo.placefinder+WHERE+text%3D%2748.2%2C+16.3667%27+and+gflags%3D%27R%27&format=json HTTP/1.1: null}{User-Agent: Java/1.8.0_65}{Host: query.yahooapis.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}
09:51:29.476 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from INITIALIZING to ONLINE
09:51:29.489 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'logging.persist'
09:51:29.504 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 9 ms
09:51:29.505 [DEBUG] [.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 1ms
09:51:29.508 [DEBUG] [.linking.impl.AbstractCleaningLinker] - doLinkModel took: 3ms
09:51:29.508 [DEBUG] [.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
09:51:29.510 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
09:51:29.517 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 6 ms
09:51:29.518 [DEBUG] [.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 1ms
09:51:29.518 [DEBUG] [.linking.impl.AbstractCleaningLinker] - doLinkModel took: 0ms
09:51:29.519 [DEBUG] [.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 1ms
09:51:29.522 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyChange'
09:51:29.528 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send message to 5/4/7, wait for confirmation
09:51:29.528 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: cEMI L-Data.req from 0.0.0 to 5/4/7, low priority hop count 6 repeat tpdu 00 00
09:51:29.530 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] KNXnet/IP Tunneling 192.168.2.7:3671: sending cEMI frame, wait for cEMI.con, attempt 1
09:51:29.535 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: confirmation of 5/4/7
09:51:29.536 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send to 5/4/7 succeeded
09:51:29.538 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'everyChange' result: everyChange
09:51:29.538 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: sent group read request to 5/4/7
09:51:29.539 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyMinute'
09:51:29.541 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'everyMinute' result: everyMinute
09:51:29.541 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'restoreOnStartup'
09:51:29.541 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'restoreOnStartup' result: restoreOnStartup
09:51:29.542 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyMinute'
09:51:29.542 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'everyMinute' result: everyMinute
09:51:29.543 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'restoreOnStartup'
09:51:29.543 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'restoreOnStartup' result: restoreOnStartup
09:51:29.567 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
09:51:29.781 [TRACE] [.www.protocol.http.HttpURLConnection] - KeepAlive stream used: https://query.yahooapis.com/v1/public/yql?q=SELECT+*+FROM+geo.placefinder+WHERE+text%3D%2748.2%2C+16.3667%27+and+gflags%3D%27R%27&format=json
09:51:29.781 [DEBUG] [.www.protocol.http.HttpURLConnection] - sun.net.www.MessageHeader@16e9cf5711 pairs: {null: HTTP/1.1 200 OK}{X-YQL-Host: main-a9c506c5-b8f8-11e5-89b6-d89d676f9644}{X-Content-Type-Options: nosniff}{Access-Control-Allow-Origin: *}{Content-Type: application/json; charset=UTF-8}{Cache-Control: public, max-age=2591999}{Date: Sun, 17 Jan 2016 08:15:34 GMT}{Age: 2155}{Server: ATS}{Content-Length: 720}{Connection: keep-alive}
09:51:29.810 [INFO ] [smarthome.event.InboxUpdatedEvent   ] - Discovery Result with UID 'yahooweather:weather:12814970' has been updated.
09:51:30.463 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
09:51:30.465 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Ignoring KNX bus data: couldn't transform to an openHAB type (not supported). Destination='5/4/7', datapoint='command DP 5/4/7 knx:ip:ip1, DPT main 0 id 9.001, low priority', data='0x86CA'
09:51:30.467 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Boolean (main type 1) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Boolean controlled (main type 2 loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 3 Bit controlled (main type 3) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 8 Bit unsigned value (main type 5) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 2 octet unsigned value (main type 7) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 2 octet float value (main type 9) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Time (main type 10) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Date (main type 11) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet unsigned value (main type 12) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet signed value (main type 13) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet float value (main type 14) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: String (main type 16) loaded
09:51:30.469 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Scene number (main type 17) loaded
09:51:30.470 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Scene control (main type 18) loaded
09:51:30.470 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Date with time (main type 19) loaded
09:51:31.222 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core
09:51:31.225 [DEBUG] [org.apache.karaf.main.Main          ] - Start level change complete.
09:51:31.225 [DEBUG] [org.eclipse.osgi                    ] - FrameworkEvent STARTLEVEL CHANGED - org.eclipse.osgi
09:51:31.572 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:51:32.461 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:51:34.752 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.5
09:51:36.488 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:51:36.491 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:51:37.545 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:51:37.609 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
09:51:40.494 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
kgoderis commented 8 years ago

pm me on karel.goderis [AT] me dot com and I will send you my jar

tbrandstetter commented 8 years ago

Thanks for the jar. What I've noticed with my and with your jar is, that it is not working with a minimal "add ons" configuration. I'm using the Openhab 2.0.0.b1 online version. Here is my addons config:

# The base installation package of this openHAB instance
# Valid options:
#   - minimal  : Installation only with dashboard, but no UIs or other addons
#   - standard : Typical installation with all standards UIs
#   - demo     : A demo setup which includes UIs, a few bindings, config files etc.
package = minimal

# A comma-separated list of bindings to install (e.g. "sonos,knx,zwave")
binding = 

# A comma-separated list of UIs to install (e.g. "basic,paper")
ui = basic,paper

# A comma-separated list of persistence services to install (e.g. "rrd4j,jpa")
persistence = rrd4j

# A comma-separated list of actions to install (e.g. "mail,pushover")
action = 

# A comma-separated list of transformation services to install (e.g. "map,jsonpath")
transformation = 

# A comma-separated list of text-to-speech engines to install (e.g. "marytts,freetts")
tts = 

# A comma-separated list of miscellaneous services to install (e.g. "myopenhab")
misc = 
10:51:51.842 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/Users/tbrandstetter/Downloads/openhab-online-2.0.0.b1/addons/org.openhab.binding.knx_2.0.0.201510051808.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.knx [10]
  Unresolved requirement: Import-Package: com.google.common.collect

    at org.eclipse.osgi.container.Module.start(Module.java:434)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:393)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1245)[8:org.apache.felix.fileinstall:3.5.0]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1217)[8:org.apache.felix.fileinstall:3.5.0]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:509)[8:org.apache.felix.fileinstall:3.5.0]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:358)[8:org.apache.felix.fileinstall:3.5.0]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:310)[8:org.apache.felix.fileinstall:3.5.0]

With full blown demo mode I have the same problem as I had with my version:

2016-01-17 11:02:40.248 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/Users/tbrandstetter/Downloads/openhab-online-2.0.0.b1/addons/org.openhab.binding.knx_2.0.0.201510051808.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.knx [166]
  Unresolved requirement: Import-Package: gnu.io

        at org.eclipse.osgi.container.Module.start(Module.java:434)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:393)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
        at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1245)[8:org.apache.felix.fileinstall:3.5.0]
        at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1217)[8:org.apache.felix.fileinstall:3.5.0]
        at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:509)[8:org.apache.felix.fileinstall:3.5.0]
        at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:358)[8:org.apache.felix.fileinstall:3.5.0]
        at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:310)[8:org.apache.felix.fileinstall:3.5.0]

As a fix I had to move the lib nrjavaserial-3.9.3.jar in the libs directory and explicitly set it in the build-path. Furthermore I had to move it from the "Import-Package" section to the "Bundle-ClassPath" section in the Manifest file and to the build.properties. After that I rebuilt the jar with "man clean install" and could use it with the "demo" configuration but not with "minimal". Can you recreate my errors?

maggu2810 commented 8 years ago

Using the addons folder will not install required bundles. If you are missing gnu.io you should not drop nrjavaserial to the addons folder but install openhab-transport-serial.

tbrandstetter commented 8 years ago

there is no such "binding" named openhab-transport-serial. Where can I find it? How can I figure out all dependencies the KNX binding needs with a minimal configuration? Sorry for the questions, but I'm new to Openhab ...

tbrandstetter commented 8 years ago

ok, found the plugin under distribution-1.8.0-runtime/server/plugins/org.openhab.io.transport.serial_1.8.0.jar

With this plugin the knx 2.0 binding starts with the "demo" configuration of Openhab 2.0.0.b1. Doesn't looks good. I have the same error as with my compiled version of it:

14:40:47.152 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'knx:ip:ip1' has been added.
14:40:47.157 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from UNINITIALIZED to INITIALIZING
14:40:47.199 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-7] KNXnet/IP Tunneling 192.168.2.7:3671: establish connection from /192.168.2.244:62102 to /192.168.2.7:3671
14:40:47.200 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-7] KNXnet/IP Tunneling 192.168.2.7:3671: wait for connect response from /192.168.2.7:3671 ...
14:40:47.204 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] KNXnet/IP Tunneling 192.168.2.7:3671: using server-assigned data endpoint /192.168.2.7:3671
14:40:47.206 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-7] KNXnet/IP Tunneling 192.168.2.7:3671: connection established
14:40:47.218 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from INITIALIZING to ONLINE
14:40:47.268 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] link 192.168.2.7:3671: send message to 5/4/7, wait for confirmation
14:40:47.268 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] link 192.168.2.7:3671: cEMI L-Data.req from 0.0.0 to 5/4/7, low priority hop count 6 repeat tpdu 00 00
14:40:47.270 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] KNXnet/IP Tunneling 192.168.2.7:3671: sending cEMI frame, wait for cEMI.con, attempt 1
14:40:47.358 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: confirmation of 5/4/7
14:40:47.359 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] link 192.168.2.7:3671: send to 5/4/7 succeeded
14:40:47.360 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] process link 192.168.2.7:3671: sent group read request to 5/4/7
14:40:47.503 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
14:40:47.504 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Ignoring KNX bus data: couldn't transform to an openHAB type (not supported). Destination='5/4/7', datapoint='command DP 5/4/7 knx:ip:ip1, DPT main 0 id 9.001, low priority', data='0x87BA'
14:40:47.505 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Boolean (main type 1) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Boolean controlled (main type 2 loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 3 Bit controlled (main type 3) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 8 Bit unsigned value (main type 5) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 2 octet unsigned value (main type 7) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 2 octet float value (main type 9) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Time (main type 10) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Date (main type 11) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 4 octet unsigned value (main type 12) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 4 octet signed value (main type 13) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: 4 octet float value (main type 14) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: String (main type 16) loaded
14:40:47.507 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Scene number (main type 17) loaded
14:40:47.508 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Scene control (main type 18) loaded
14:40:47.508 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-4] DPTXlator: Date with time (main type 19) loaded
14:40:49.483 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.4
14:40:51.435 [TRACE] [javax.jmdns.impl.tasks.RecordReaper ] - RecordReaper(Thomass-Air-internal-brandstetter-co-at.local.).run() JmDNS reaping cache
14:40:51.435 [TRACE] [javax.jmdns.impl.JmDNSImpl          ] - Thomass-Air-internal-brandstetter-co-at.local..updating record for event: [ServiceEventImpl@416702720 
    name: 'TPhone-11598.local.' type: '_tcp.ip6.arpa.' info: '[ServiceInfoImpl@878176983 name: '3.3.B.7.9.5.5.D.4.4.F.7.8.0.0.0.0.0.0.0.C.2.5.F.3.7.9.3.D.3.D.F._tcp.ip6.arpa.' address: '(null):0' status: 'DNS: Thomass-Air-internal-brandstetter-co-at.local. [Thomass-Air.internal.brandstetter.co.at/192.168.2.244] state: probing 1 task: null', has NO data empty]'] list [] operation: Remove
14:40:51.435 [TRACE] [javax.jmdns.impl.JmDNSImpl          ] - Thomass-Air-internal-brandstetter-co-at.local..updating record for event: [ServiceEventImpl@1843468937 
    name: 'TPhone-11598.local.' type: '_tcp.ip6.arpa.' info: '[ServiceInfoImpl@1250138979 name: 'E.F.E.A.5.F.5.0.2.9.6.3.F.1.4.1.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F._tcp.ip6.arpa.' address: '(null):0' status: 'DNS: Thomass-Air-internal-brandstetter-co-at.local. [Thomass-Air.internal.brandstetter.co.at/192.168.2.244] state: probing 1 task: null', has NO data empty]'] list [] operation: Remove
14:40:51.436 [TRACE] [javax.jmdns.impl.JmDNSImpl          ] - Thomass-Air-internal-brandstetter-co-at.local..updating record for event: [ServiceEventImpl@1635134802 
    name: 'TPhone-11598.local.' type: '_tcp.in-addr.arpa.' info: '[ServiceInfoImpl@1794929401 name: '182.2.168.192._tcp.in-addr.arpa.' address: '(null):0' status: 'DNS: Thomass-Air-internal-brandstetter-co-at.local. [Thomass-Air.internal.brandstetter.co.at/192.168.2.244] state: probing 1 task: null', has NO data empty]'] list [] operation: Remove
14:40:51.922 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
14:40:52.849 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
14:40:53.867 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
14:40:54.028 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
14:40:56.172 [TRACE] [javax.jmdns.impl.tasks.RecordReaper ] - RecordReaper(Thomass-Air-internal-brandstetter-co-at.local.).run() JmDNS reaping cache
14:40:56.416 [TRACE] [javax.jmdns.impl.tasks.RecordReaper ] - RecordReaper(Thomass-Air-internal-brandstetter-co-at.local.).run() JmDNS reaping cache
14:40:56.838 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
14:40:56.842 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
14:40:57.873 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
14:40:59.192 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.5
14:40:59.909 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
gnih commented 8 years ago

Hi,

Same here : everything works fine in 1.5 & 1.8 but in 2.0.0b1 I can only use switches. Values are not read anymore. Btw I'm new to OH 2 and I don't now much about things and channels, would you have any link with explanation?

Thank you!

kgoderis commented 8 years ago

Without a TRACE on the knx binding itself it is hard to determine what is going wrong here.

tbrandstetter commented 8 years ago

Good morning,

what I've done so far to enable tracing. I tried to use the logback.xml in runtime/etc (Openhab2 seems to have a different path for it). I don't know if the logback.xml has a different format for Openhab2 or not.

I too have configured the logs to use tracing in Karafa with log:set TRACE. Do you have another hint for me, how I can get the plugin to spit out more? The only information I'm getting actually out of the binding is:

2016-01-18 07:12:10.071 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'knx:ip:ip1' has been added.
2016-01-18 07:12:10.077 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from UNINITIALIZED to INITIALIZING
2016-01-18 07:12:10.144 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-1] KNXnet/IP Tunneling 192.168.2.7:3671: establish connection from /192.168.2.244:65408 to /192.168.2.7:3671
2016-01-18 07:12:10.146 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-1] KNXnet/IP Tunneling 192.168.2.7:3671: wait for connect response from /192.168.2.7:3671 ...
2016-01-18 07:12:10.197 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] KNXnet/IP Tunneling 192.168.2.7:3671: using server-assigned data endpoint /192.168.2.7:3671
2016-01-18 07:12:10.198 [INFO ] [tuwien.auto.calimero                ] - [ESH-safeCall-1] KNXnet/IP Tunneling 192.168.2.7:3671: connection established
2016-01-18 07:12:10.211 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'knx:ip:ip1' changed from INITIALIZING to ONLINE
2016-01-18 07:12:10.223 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'logging.persist'
2016-01-18 07:12:10.245 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 10 ms
2016-01-18 07:12:10.245 [DEBUG] [.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
2016-01-18 07:12:10.247 [DEBUG] [.linking.impl.AbstractCleaningLinker] - doLinkModel took: 2ms
2016-01-18 07:12:10.247 [DEBUG] [.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 0ms
2016-01-18 07:12:10.249 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2016-01-18 07:12:10.255 [DEBUG] [er.antlr.AbstractInternalAntlrParser] - Parsing took: 5 ms
2016-01-18 07:12:10.255 [DEBUG] [.linking.impl.AbstractCleaningLinker] - beforeModelLinked took: 0ms
2016-01-18 07:12:10.258 [DEBUG] [.linking.impl.AbstractCleaningLinker] - doLinkModel took: 3ms
2016-01-18 07:12:10.259 [DEBUG] [.linking.impl.AbstractCleaningLinker] - afterModelLinked took: 1ms
2016-01-18 07:12:10.261 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send message to 5/4/7, wait for confirmation
2016-01-18 07:12:10.261 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: cEMI L-Data.req from 0.0.0 to 5/4/7, low priority hop count 6 repeat tpdu 00 00
2016-01-18 07:12:10.262 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyChange'
2016-01-18 07:12:10.263 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] KNXnet/IP Tunneling 192.168.2.7:3671: sending cEMI frame, wait for cEMI.con, attempt 1
2016-01-18 07:12:10.286 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'everyChange' result: everyChange
2016-01-18 07:12:10.286 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyMinute'
2016-01-18 07:12:10.288 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'everyMinute' result: everyMinute
2016-01-18 07:12:10.288 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'restoreOnStartup'
2016-01-18 07:12:10.288 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'restoreOnStartup' result: restoreOnStartup
2016-01-18 07:12:10.290 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'everyMinute'
2016-01-18 07:12:10.292 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'everyMinute' result: everyMinute
2016-01-18 07:12:10.292 [DEBUG] [t.linking.impl.DefaultLinkingService] - before getLinkedObjects: node: 'restoreOnStartup'
2016-01-18 07:12:10.294 [DEBUG] [t.linking.impl.DefaultLinkingService] - after getLinkedObjects: node: 'restoreOnStartup' result: restoreOnStartup
2016-01-18 07:12:10.320 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2016-01-18 07:12:10.364 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: confirmation of 5/4/7
2016-01-18 07:12:10.364 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send to 5/4/7 succeeded
2016-01-18 07:12:10.365 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: sent group read request to 5/4/7
2016-01-18 07:12:11.369 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: timeout waiting for group read response
2016-01-18 07:12:11.370 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Cannot read value for datapoint '5/4/7' from KNX bus: timeout waiting for group read response
2016-01-18 07:12:11.421 [INFO ] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send message to 5/4/7, wait for confirmation
2016-01-18 07:12:11.421 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: cEMI L-Data.req from 0.0.0 to 5/4/7, low priority hop count 6 repeat tpdu 00 00
2016-01-18 07:12:11.421 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] KNXnet/IP Tunneling 192.168.2.7:3671: sending cEMI frame, wait for cEMI.con, attempt 1
2016-01-18 07:12:11.855 [DEBUG] [mpl.info.InfoBundleTrackerCustomizer] - Ignore incorrect info null provided by bundle org.openhab.core
2016-01-18 07:12:11.857 [DEBUG] [org.eclipse.osgi                    ] - FrameworkEvent STARTLEVEL CHANGED - org.eclipse.osgi
2016-01-18 07:12:11.857 [DEBUG] [org.apache.karaf.main.Main          ] - Start level change complete.
2016-01-18 07:12:12.310 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
2016-01-18 07:12:12.310 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: confirmation of 5/4/7
2016-01-18 07:12:12.310 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] link 192.168.2.7:3671: send to 5/4/7 succeeded
2016-01-18 07:12:12.311 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] process link 192.168.2.7:3671: sent group read request to 5/4/7
2016-01-18 07:12:12.313 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.10
2016-01-18 07:12:12.313 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Ignoring KNX bus data: couldn't transform to an openHAB type (not supported). Destination='5/4/7', datapoint='command DP 5/4/7 knx:ip:ip1, DPT main 0 id 9.001, low priority', data='0x85C6'
2016-01-18 07:12:12.313 [WARN ] [nx.handler.KNXBridgeBaseThingHandler] - Ignoring KNX bus data: couldn't transform to an openHAB type (not supported). Destination='5/4/7', datapoint='command DP 5/4/7 knx:ip:ip1, DPT main 0 id 9.001, low priority', data='0x85C6'
2016-01-18 07:12:12.315 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.5
2016-01-18 07:12:12.316 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Boolean (main type 1) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Boolean controlled (main type 2 loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 3 Bit controlled (main type 3) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 8 Bit unsigned value (main type 5) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 2 octet unsigned value (main type 7) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 2 octet float value (main type 9) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Time (main type 10) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Date (main type 11) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet unsigned value (main type 12) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet signed value (main type 13) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: 4 octet float value (main type 14) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: String (main type 16) loaded
2016-01-18 07:12:12.318 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Scene number (main type 17) loaded
2016-01-18 07:12:12.319 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Scene control (main type 18) loaded
2016-01-18 07:12:12.319 [DEBUG] [tuwien.auto.calimero                ] - [ESH-thingHandler-2] DPTXlator: Date with time (main type 19) loaded
2016-01-18 07:12:14.155 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:15.169 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:16.161 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:19.169 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:19.172 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:20.205 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:22.156 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:22.184 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:23.156 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:27.174 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:27.177 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:28.181 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:28.187 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:31.253 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:35.819 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.5
2016-01-18 07:12:36.155 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:39.160 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:39.229 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2016-01-18 07:12:44.155 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:45.165 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:46.203 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:47.841 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.5
2016-01-18 07:12:49.146 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:49.174 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:50.196 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:52.213 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:52.216 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:53.195 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:54.329 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.4
2016-01-18 07:12:57.160 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:57.169 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:58.185 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:12:58.187 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:00.023 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
2016-01-18 07:13:00.023 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job rrd4j.everyMinute
2016-01-18 07:13:01.166 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:06.201 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:06.387 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.4
2016-01-18 07:13:09.257 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:10.202 [DEBUG] [tuwien.auto.calimero                ] - [KNXnet/IP heartbeat monitor] KNXnet/IP Tunneling 192.168.2.7:3671: sending connection state request, attempt 1
2016-01-18 07:13:14.309 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:15.182 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:15.899 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.9
2016-01-18 07:13:16.206 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:19.148 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:19.172 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:20.209 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:22.171 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:22.184 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:23.169 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:27.163 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:27.170 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:28.193 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:28.196 [INFO ] [tuwien.auto.calimero                ] - [KNXnet/IP receiver] link 192.168.2.7:3671: indication from 1.1.8
2016-01-18 07:13:29.746 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 0 triggers
kgoderis commented 8 years ago

I need to check this as I am myself still running my env. on a pre-Karaf snapshot.

kaikreuzer commented 8 years ago

I can reproduce the problem and it is not a problem of the binding as it seems - I have created https://github.com/openhab/openhab-distro/issues/96 for digging deeper into the underlying cause...

tbrandstetter commented 8 years ago

Makes sense, because as I stated in the beginning it is not working with the KNX binding 1.8 either.